5.0.0

Changes

• KOJO-91: Terminally panic a job that throws uncaught exceptions instead of crash-looping. If retrying a job when an uncaught exception is thrown is desirable behavior, the exception must be caught in userspace, and the Worker Service API must be used to request a retry.
• KOJO-157 Remove the following top-level logging keys in favor the of the kojo_metadata structure as documented in the 4.15.0 release notes:
  • kojo_process
  • kojo_job
  • process_id
  • process_path

Sandboxed JobStateChangelogProcessor and README update

• README update
• JSCLP process, and JSC table migration and model

Log Metadata object with job, process, and host information

Changes

• Add kojo_metadata object to logging structure that contains job, process and host keys.
• In the kojo_metadata.host object there is:
  • host_name: Contains the gethostname() results. On docker this is just a hash of the container ID, but on EC2 or Kubernetes it will be a more verbose string.
  • load_average: the instantaneous Load average that is also sampled by canEnvironmentSustainAdditionProcesses()
• In the kojo_metadata.process object you can find memory stats for the process that executing your Kōjō job.
  • memory_usage_bytes: current memory allocated to the PHP process via emalloc()
  • memory_peak_usage_bytes: peak memory allocated
  • memory_limit_bytes: The results of ini_get('memory_limit') string like '128M' normalized into bytes.

Example output

Example dashboard: https://snapshot.raintank.io/dashboard/snapshot/C9KwxOAe2rugM73YIDikDUyN7ezmoz9d?orgId=2

{
    "time": "Thu, 19 Sep 19 13:38:44.508414 UTC",
    "level": "notice",
    "message": "Got lucky this time boss!",
    "context": {
        "event_type": "task_status",
        "top_level_status": "success",
        "nested_object": {
            "random_letters": "bright",
            "random_word": "materialization",
            "random_value": 25,
            "status": "success"
        }
    },
    "context_json_last_error": 0,
    "kojo_metadata": {
        "job": {
            "kojo_job_id": 8268,
            "type_code": "complex_logging_structure",
            "name": "Protean DLCP Example",
            "priority": 7,
            "importance": 10,
            "work_at_date_time": "2019-09-19 13:38:27",
            "next_state_request": "none",
            "assigned_state": "working",
            "previous_state": "crashed",
            "worker_uri": "Neighborhoods\\KojoFitnessUseCase46\\V1\\Worker\\Facade",
            "worker_method": "start",
            "can_work_in_parallel": true,
            "last_transition_date_time": "2019-09-19 13:38:43",
            "last_transition_micro_time": "1568900323188672",
            "times_worked": 4,
            "times_retried": 0,
            "times_held": 0,
            "times_crashed": 3,
            "times_panicked": 0,
            "created_at_date_time": "2019-09-19 13:38:27",
            "completed_at_date_time": null,
            "delete_after_date_time": null
        },
        "process": {
            "process_id": 7750,
            "parent_process_id": 7240,
            "path": "\/server[7236]\/root[7240]\/job[7750]",
            "uuid": "af35fa582d5b-172.21.0.7-\/server[7236]\/root[7240]\/job[7750]-1568900322.717618-2585409713",
            "type_code": "job",
            "memory_usage_bytes": 10681168,
            "memory_peak_usage_bytes": 10722400,
            "memory_limit_bytes": 134217728
        },
        "host": {
            "host_name": "af35fa582d5b",
            "load_average": 4.83
        }
    }
}

Modify watchdog to use one named redis connection

• #78

Add robustness around redis command processing

• #75

Serialize and log kojo_job table for each log message emitted by the logger

This adds a new top level key kojo_job that contains the state of the Data\Job object which reflects what is in the kojo_job database table. Here is an example message with the new kojo_job message:

{
  "time": "Tue, 27 Aug 19 14:02:16.008313 UTC",
  "level": "notice",
  "process_id": "240",
  "process_path": "\/server[201]\/root[205]\/job[240]",
  "kojo_job": {
    "kojo_job_id": 16,
    "type_code": "complex_logging_structure",
    "name": "Protean DLCP Example",
    "priority": 10,
    "importance": 10,
    "work_at_date_time": "2019-08-27 14:02:09",
    "next_state_request": "none",
    "assigned_state": "working",
    "previous_state": "waiting",
    "worker_uri": "Neighborhoods\\KojoFitnessUseCase46\\V1\\Worker\\Facade",
    "worker_method": "start",
    "can_work_in_parallel": true,
    "last_transition_date_time": "2019-08-27 14:02:15",
    "last_transition_micro_time": "1566914535331998",
    "times_worked": 1,
    "times_retried": 0,
    "times_held": 0,
    "times_crashed": 0,
    "times_panicked": 0,
    "created_at_date_time": "2019-08-27 14:02:09",
    "completed_at_date_time": null,
    "delete_after_date_time": null
  },
  "message": "Got lucky this time boss!",
  "context": {
    "event_type": "task_status",
    "top_level_status": "success",
    "nested_object": {
      "random_letters": "crmls",
      "random_word": "ingestion",
      "random_value": 11,
      "status": "success"
    }
  },
  "context_json_last_error": 0
}

Useful things this provides:

• The kojo_job.type_code will provide a standard way to aggregate jobs in elasticsearch
• Monitoring the kojo_job.times_crashed or times_panicked will provide insight into reoccurring issues
• Checking kojo_job.assigned_state will help reveal if pseudo-success messages are being emitted from userspace before the job calls $this->getApiV1WorkerService()->requestCompleteSuccess()->applyRequest(); which can reveal logical flow errors.

Client specified signal buffering per signal

Improve the behavior when worker processes are sent SIGCHILD signals when the environment kills mutex processes.

Add 'json_pretty_print' logging format

• Remove exception_string from context array since the exception is now being fully normalized
• Setting the following config value in will result logging being formatted with the JSON_PRETTY_PRINT option.

process.pool.logger.formatter.log_format: 'json_pretty_print'

This is useful to bypass docker logging driver line limits of 16KB since each new line is passed as its own record.

In practice, log messages go from looking like:

{"time":"Mon,06May1921:12:17.760256UTC","level":"notice","process_id":"78","process_path":"\/server[16]\/root[20]\/job[78]","message":"working","context":{"job_type":"complex_logging_structure","event_type":"working"},"context_json_last_error":0}

to looking like

{
    "time": "Mon, 06 May 19 21:12:17.760256 UTC",
    "level": "notice",
    "process_id": "78",
    "process_path": "\/server[16]\/root[20]\/job[78]",
    "message": "working",
    "context": {
        "job_type": "complex_logging_structure",
        "event_type": "working"
    },
    "context_json_last_error": 0
}

Improve error logging

• Add error_get_last() information to unexpected shutdown event
• Pass exceptions as an object under the 'exception' key, and normalize that key if it's a throwable

Quality of Life improvements

• Allow database port to be configured using neighborhoods.kojo.environment.parameters.database_port parameter
• Gracefully handle disabled statically scheduled job types. If the first job in the kojo_job table is disabled it will no longer prevent other jobs from being worked
• Allow the repeated use of (new Kojo\Api\V1\Job\Type\Service())->addYmlServiceFinder($finder)->getNewJobTypeRegistrar() by removing shallow cloning
• This library defaults to whatever date_default_timezone_get() is, make it explicit that we want to use UTC