{"action":"created","issue":{"url":"https://api.github.com/repos/broadinstitute/cromwell/issues/44","labels_url":"https://api.github.com/repos/broadinstitute/cromwell/issues/44/labels{/name}","comments_url":"https://api.github.com/repos/broadinstitute/cromwell/issues/44/comments","events_url":"https://api.github.com/repos/broadinstitute/cromwell/issues/44/events","html_url":"https://github.com/broadinstitute/cromwell/pull/44","id":88180071,"number":44,"title":"Better logging, more docs, fix duplicate call actor bug","user":{"login":"scottfrazer","id":58551,"avatar_url":"https://avatars.githubusercontent.com/u/58551?v=3","gravatar_id":"","url":"https://api.github.com/users/scottfrazer","html_url":"https://github.com/scottfrazer","followers_url":"https://api.github.com/users/scottfrazer/followers","following_url":"https://api.github.com/users/scottfrazer/following{/other_user}","gists_url":"https://api.github.com/users/scottfrazer/gists{/gist_id}","starred_url":"https://api.github.com/users/scottfrazer/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/scottfrazer/subscriptions","organizations_url":"https://api.github.com/users/scottfrazer/orgs","repos_url":"https://api.github.com/users/scottfrazer/repos","events_url":"https://api.github.com/users/scottfrazer/events{/privacy}","received_events_url":"https://api.github.com/users/scottfrazer/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":8,"created_at":"2015-06-14T12:51:56Z","updated_at":"2015-06-15T10:53:00Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/broadinstitute/cromwell/pulls/44","html_url":"https://github.com/broadinstitute/cromwell/pull/44","diff_url":"https://github.com/broadinstitute/cromwell/pull/44.diff","patch_url":"https://github.com/broadinstitute/cromwell/pull/44.patch"},"body":"![screen shot 2015-06-14 at 8 36 19 am](https://cloud.githubusercontent.com/assets/58551/8148606/0f7b94f6-1273-11e5-8f6e-8fb7b23aa935.png)\r\n\r\n\r\nNo rush to review this (but it does fix a bug).  This is ancillary to the sprint but it'd be nice if we could get it in by the end of the sprint.\r\n\r\nChanges:\r\n\r\n1)  SLF4J logging hooked in with the actor system too.\r\n\r\n2)  Two modes of logging, set by the Java Property `CROMWELL_LOGGER=[SERVER|CONSOLE]`:\r\n\r\n  * In SERVER mode, it logs to a rolling file appender with all the bells and whistles.  This will default to DEBUG level.\r\n  * In CONSOLE mode, there's code in `cromwell.logging` that handles these messages from SLF4J and prints them out to the console is as human-readable way as possible.  I welcome comments about how to make it more readable.  Though, if you are going to do that make sure you first run it so you can see the colors, which are an important aspect of this!  CONSOLE logs on INFO, WARN, ERROR.\r\n  * The modes are toggled either by explicitly setting CROMWELL_LOGGER, or based on the CLI sub-command you chose:  `server` will do SERVER logging and every other sub-command uses CONSOLE logging.\r\n\r\n3)  I've tried to establish some conventions for logging:\r\n\r\n  * INFO, WARN, ERROR is meant to be read by *users* to debug their WDL executions.  It should equally be helpful for *developers* to debug many issues.  We must keep in mind that these are also show up in the server logs so they could also help us add context to debugging an issue easier if we're used to these messages from the command line.\r\n  * Messages should contain the workflow UUID wherever appropriate.  Anything that exists only in a context of a workflow execution: CallActors, WorkflowActors, SymbolStores, etc.\r\n  * Messages should be chosen to craft a story about how a workflow is progressing.  Highlight the big points (something starts, something finishes, something is launched, symbol store entry is updated, etc)\r\n\r\n4) **Bug fix**: In my testing I came across this interesting concurrency bug:\r\n\r\nTake the 3-step workflow, and call 'ps' two more times in parallel with the first one.  It launches 3 'ps' commands, then they all finish at pretty much the exact same time and report finished which triggers up to 3 calls to findRunnableCalls to be piped to the workflow actor.  My bug fix adds the ability to *reserve* a call by requesting that the StoreActor, instead of doing `updateStatus(call, status)` now has `updateStatusFrom(call, fromStatus, toStatus): Boolean`.  The boolean return value signifies if it was able to perform that action.  Since actors are single threaded, it is guaranteed that one-and-only one call to `updateStatusFrom` with the same parameters will return `true`.  That return value is used by the WorkflowActor to decide to launch a job.  Basically it says \"Can I set this call from NotStarted to Started?  yes?  okay then that means I should launch it.  No?  Okay that means I already launched it.\"\r\n\r\nNow that I think about it there might be a better way to do this.\r\n\r\nTo further my point that attention to logging is VERY important... the only reason I was able to diagnose that bug so fast was that the logging I had just implemented tipped me off right away to the places to look.  Running it a few times, it was immediately apparent that the downstream jobs were getting run roughly 1 to 3 times.  Sometimes things would run great, sometimes it'd loop for a very long time.  Sometimes it'd stop after a few duplicate launches."},"comment":{"url":"https://api.github.com/repos/broadinstitute/cromwell/issues/comments/112017128","html_url":"https://github.com/broadinstitute/cromwell/pull/44#issuecomment-112017128","issue_url":"https://api.github.com/repos/broadinstitute/cromwell/issues/44","id":112017128,"user":{"login":"scottfrazer","id":58551,"avatar_url":"https://avatars.githubusercontent.com/u/58551?v=3","gravatar_id":"","url":"https://api.github.com/users/scottfrazer","html_url":"https://github.com/scottfrazer","followers_url":"https://api.github.com/users/scottfrazer/followers","following_url":"https://api.github.com/users/scottfrazer/following{/other_user}","gists_url":"https://api.github.com/users/scottfrazer/gists{/gist_id}","starred_url":"https://api.github.com/users/scottfrazer/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/scottfrazer/subscriptions","organizations_url":"https://api.github.com/users/scottfrazer/orgs","repos_url":"https://api.github.com/users/scottfrazer/repos","events_url":"https://api.github.com/users/scottfrazer/events{/privacy}","received_events_url":"https://api.github.com/users/scottfrazer/received_events","type":"User","site_admin":false},"created_at":"2015-06-15T10:53:00Z","updated_at":"2015-06-15T10:53:00Z","body":"I agree with you about the approach to fix the bug, I'm unclear about who is moving the code over to the new branch.  I'll do it, but I just wanted to make sure nobody else was first..."}}