Skip to content

Instantly share code, notes, and snippets.

@kporangehat

kporangehat/gist:4588193

Last active December 11, 2015 10:38
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save kporangehat/4588193 to your computer and use it in GitHub Desktop.
Save kporangehat/4588193 to your computer and use it in GitHub Desktop.
Download ZIP
Shotgun production log format
Raw
gistfile1.md

Overview

The production log can be useful for installed clients who want to monitor, diagnose, or report on the granular usage of Shotgun. Because the production log is a log file located on the Shotgun server itself, this is only available for installed clients.

This format may change without warning
This format may (and probably will) change from time to time as we adjust and tweak the output to better match the needs of our clients. Please keep this in mind if you write tools for parsing, etc. We will make every attempt to keep this document up to date, but changes might not be documented immediately. So rely on this at your own peril ;)

General Log Format

(Date) (Log Level) (Hostname) (Process[Pid]): (Type): (time taken in ms - optional ) (Key Value pairs - optional) (-- (Message - text, sql, or json) optional)

Date format - 2013-01-14T18:02:33-0800

Common Types

  • CRUD.* - CRUD requests
  • SQL.(.) - Sql generated by the Query module
  • Controller. - Rails Controllers
  • Memcached(.*)
  • Passenger
  • TRANSCODE(.*)

Common Keys for KV pairs

  • request_id - unique alpha numeric id for each request received by Rails.
  • user - user login
  • api_user - api script name
  • db - postgres database name
  • page_id - shotgun page id
  • widget
  • method - http method
  • status - http status code
  • uri
  • remote_ip
  • session_id - rails session id

Example Log Messages

Controller Begin Request:

2013-01-10T11:25:10-0800 INFO zapp rails[11694]: CrudController.requests: db=performance 
    request_id=b82a7a53610431cdfdeb1fe75e972052 method=POST uri=/crud/requests remote_ip=127.0.0.1 
    session_id=6e42723b7577adc3a142cef481ece4b5 user=shotgun_admin

Controller End Request:

2013-01-10T11:25:10-0800 INFO zapp rails[11694]: CrudController.requests: 20.1409ms db=performance 
    request_id=ddee710f80f9996b7b1c678eca7615d3 method=POST status=200 uri=/crud/requests remote_ip=127.0.0.1
    session_id=6e42723b7577adc3a142cef481ece4b5 user=shotgun_admin

SQL:

2013-01-10T11:25:10-0800 INFO zapp rails[11694]: SQL.summarize: 0.3720ms db=performance page_id=1304 
    widget=body request_id=ddee710f80f9996b7b1c678eca7615d3 user=shotgun_admin -- SELECT COUNT(*) AS
    a_id_record_count FROM shots a WHERE ( ( ( ( ( ( a.project_id = 4 ) ) ) AND ( ( a.sg_sequence_type = 
    'Sequence' AND a.sg_sequence_id = 2 ) ) ) ) ) AND a.retirement_date IS NULL

2013-01-14T17:50:30-0800 INFO zapp rails[46898]: SQL.preload.belongs_to: 0.9700ms db=performance page_id=35
    widget=body request_id=f5fe38fc00bbd0b2f49af8c1f2337a77 user=shotgun_admin -- SELECT
    "permission_rule_sets".id, dnc.display_name AS name, dnc.sg_status_list AS status,
    "permission_rule_sets".uuid as uuid FROM "permission_rule_sets" LEFT JOIN display_name_caches dnc ON
    "permission_rule_sets".id=dnc.entity_id AND dnc.entity_type='PermissionRuleSet' WHERE
    "permission_rule_sets".id IN (6) AND "permission_rule_sets".retirement_date IS NULL

2013-01-14T17:50:30-0800 INFO zapp rails[46898]: SQL.find: 2.5970ms db=performance page_id=35 widget=body 
    request_id=f5fe38fc00bbd0b2f49af8c1f2337a77 user=shotgun_admin -- SELECT a.id, a.firstname, a.role_id,
    a.lastname, a.email, a.description, a.generate_event_log_entries FROM users a WHERE a.retirement_date IS
    NULL AND a.type = 'ApiUser' ORDER BY a.id asc NULLS LAST LIMIT 25 OFFSET 0

2013-01-14T17:50:30-0800 INFO zapp rails[46898]: SQL.preload.has_many_through: 0.8320ms db=performance 
    request_id=f5fe38fc00bbd0b2f49af8c1f2337a77 user=shotgun_admin -- SELECT
    array_to_string(array_agg("users".id), ',') AS source_ids, dnc.entity_id AS id, dnc.display_name AS
    name, dnc.sg_status_list AS status FROM "users" LEFT JOIN "banner_user_connections" ON
    "users".id="banner_user_connections".user_id  LEFT JOIN "banners" ON
    "banner_user_connections".banner_id="banners".id LEFT JOIN display_name_caches dnc ON
    dnc.entity_type='Banner' AND dnc.entity_id="banners".id WHERE "users".id IN (24) AND "banners".id IS NOT
    NULL AND banners.retirement_date IS NULL AND banner_user_connections.retirement_date IS NULL GROUP BY
    dnc.entity_id, dnc.display_name, dnc.sg_status_list

CRUD

Summarize

2013-01-10T11:25:10-0800 INFO zapp rails[11694]: CRUD.summarize: 12.4310ms db=performance page_id=1304
    widget=body request_id=ddee710f80f9996b7b1c678eca7615d3 user=shotgun_admin --
    {"type":"Shot","local_timezone_offset":-8,"filters":{"conditions":[{"conditions":[{"conditions":
    [{"values":[{"name":"Demo Project","type":"Project","id":4,"uuid":"9d4243ce-0302-11df-b8e3-00304898dbee","valid":"valid"}],
    "relation":"is","path":"project","active":"true"}],"logical_operator":"and","active":"true"},
    {"conditions":[{"conditions":[],"logical_operator":"and","active":"true"}],"logical_operator":"and","active":"true"}],
    "logical_operator":"and"},{"conditions":[{"values":[{"name":"Sequence 1","type":"Sequence","id":2,"valid":"valid"}],
    "relation":"is","path":"sg_sequence","active":true}],"logical_operator":"and"}],"logical_operator":"and"},
    "source_widget":{"page_id":1304,"widget":"body"},"summaries":[{"type":"record_count","column":"id"}],"request_type":"summarize"}

Read

2013-01-14T17:42:55-0800 INFO zapp rails[46898]: CRUD.read: 85.9250ms db=performance page_id=1304 
    widget=body request_id=d4900359e5f9b188b3d3879921bc7337 user=shotgun_admin -- {"columns":
    ["code","sg_status_list","image","sg_sequence","description","sg_cut_in","sg_cut_out","sg_cut_duration",
    "project","filmstrip_image"],"paging":{"records_per_page":50,"current_page":1},"grouping":
    [{"column":"sg_sequence","method":"exact","direction":"asc"}],"sorts":[],"read":
    ["entities","paging_info","groups"],"type":"Shot","local_timezone_offset":-8,"filters":
    {"conditions":[{"conditions":[{"values":[{"name":"Demo Project","type":"Project","id":4,"uuid":"9d4243ce-0302-11df-b8e3-00304898dbee","valid":"valid"}],
    "relation":"is","path":"project","active":"true"}],"logical_operator":"and","active":"true"},
    {"conditions":[{"conditions":[],"logical_operator":"and","active":"true"}],"logical_operator":"and","active":"true"}],
    "logical_operator":"and"},"source_widget":{"page_id":1304,"widget":"body"},"request_type":"read"}

Group Summarize

2013-01-14T17:43:29-0800 INFO zapp rails[46898]: CRUD.group_summarize: 13.1890ms db=performance page_id=1304
    widget=body request_id=c6261e1ced726c17dba69a75d975c72b user=shotgun_admin -- {"paging":
    {"records_per_page":200,"current_page":1},"grouping":[{"column":"assets","method":"exact","direction":"asc"}],
    "type":"Shot","local_timezone_offset":-8,"filters":{"conditions":[{"conditions":[{"values":
    [{"name":"Demo Project","type":"Project","id":4,"uuid":"9d4243ce-0302-11df-b8e3-00304898dbee","valid":"valid"}],"relation":"is","path":"project","active":"true"}],
    "logical_operator":"and","active":"true"},{"conditions":[{"conditions":[],"logical_operator":"and","active":"true"}],"logical_operator":"and","active":"true"},
    {"conditions":[],"logical_operator":"and"}],"logical_operator":"and"},"source_widget":
    {"page_id":1304,"widget":"body"},"summaries":[{"type":"record_count","column":"id"}],"request_type":"group_summarize"}

Update

2013-01-14T17:43:59-0800 INFO zapp rails[46924]: CRUD.update: 125.6700ms db=performance 
    request_id=cee241af38cd490dee18df9d4fe619e5 user=shotgun_admin -- 
    {"column":"description","type":"Shot","local_timezone_offset":-8,"id":5,"value":"testing",
    "request_type":"update"}

Delete

2013-01-14T17:44:57-0800 INFO zapp rails[46924]: CRUD.delete: 2867.8530ms db=performance 
    request_id=315a34160094b143a82f3e9534fdd4c7 user=shotgun_admin -- 
    {"type":"Shot","local_timezone_offset":-8,"id":5,"request_type":"delete"}

Memcached

2013-01-10T11:25:10-0800 INFO zapp rails[11711]: Memcached:  -- Uninitializing memcached
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached.get.miss: key=schema 
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached:  -- General validation keys set to 0
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached.get.miss: key=globals 
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached:  -- General validation keys set to 0
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached.get.miss: key=permitted_projects 
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached:  -- General validation keys set to 0
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached.get.miss: key=admin_pages 
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached:  -- General validation keys set to 0
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached.get.miss: key=api3_schema 
2013-01-14T18:02:48-0800 INFO zapp rails[47653]: Memcached:  -- General validation keys set to 0
2013-01-14T18:02:50-0800 INFO zapp rails[47664]: Passenger: Spawned new process. Reconnecting to memcached. 
2013-01-14T18:02:50-0800 INFO zapp rails[47664]: Memcached:  -- Uninitializing memcached
2013-01-14T18:02:50-0800 INFO zapp rails[47664]: Memcached:  -- Initializing connection with $memcached_config = {:options=>{:prefix_key=>"performance-r38441"}, :ip_and_port_string=>"127.0.0.1:12345"}

Passenger

2013-01-10T11:25:10-0800 INFO zapp rails[11711]: Passenger: Spawned new process. Reconnecting to memcached.

HTML rendering

2013-01-10T11:25:10-0800 INFO zapp rails[11694]: Rendering 
    /Users/brandonvfx/swdevl/sg/shotgun/trunk/app/views/page/server_error_page.rhtml (500) user=shotgun_admin

API Related

SQL
2013-01-14T17:57:59-0800 INFO zapp rails[46898]: SQL.find: 0.4020ms db=performance 
    api_user=performance_test -- SELECT a.id FROM projects a WHERE a.retirement_date IS NULL 
    ORDER BY a.id asc NULLS LAST LIMIT 500 OFFSET 0

CRUD

2013-01-14T17:57:59-0800 INFO zapp rails[46898]: CRUD.read: 7.9170ms db=performance 
    api_user=performance_test -- {"api_return_image_urls":true,"columns":["id"],"paging":
    {"records_per_page":500,"current_page":1},"sorts":[{"column":"id","direction":"asc"}],"read":
    ["entities","paging_info"],"type":"Project","filters":{"conditions":
    [],"logical_operator":"and"},"request_type":"read"}

Controller

2013-01-14T17:57:59-0800 INFO zapp rails[46898]: Api3Controller.json: 22.7349ms db=performance 
    request_id=2adbead05020694741d7c9dc54132cc0 method=POST status=200 uri=/api3/json 
    remote_ip=127.0.0.1 api_user=performance_test
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment