Creating executions fails due to unserializible date (running from sources)

[winem]

SUMMARY

I followed these docs: https://docs.stackstorm.com/development/sources.html

Whenever I try to trigger an action st2 / the API I get the following error:

st2 run core.local uname
ERROR: 500 Server Error: Internal Server Error
MESSAGE: datetime.datetime(2020, 4, 13, 23, 9, 54, 712681, tzinfo=tzutc()) is not JSON serializable for url: http://127.0.0.1:9101/v1/executions

STACKSTORM VERSION

st2 3.2dev, on Python 3.6.9

I'm currently at this commit: f5e56ac

OS, environment, install method

uname -a 
Linux ITS0873 5.3.0-46-generic #38~18.04.1-Ubuntu SMP Tue Mar 31 04:17:56 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

# with activated virtualenv
python -V
Python 3.6.9

virtualenv --version
virtualenv 20.0.16 from /home/marcel/.local/lib/python3.6/site-packages/virtualenv/__init__.py

(It's the same with Python2.7 and the default virtual env. I just tried both to be sure.)

These are the used backends running in docker containers with the env files as being provided with the st2-docker project:

rabbitmq:3.6-management
mongo:3.4
redis:4.0
postgres:9.6

Steps to reproduce the problem

The steps from the docs up to Verify Installation. st2 action list works fine.
https://docs.stackstorm.com/development/sources.html

Expected Results

Expected to have a newly created execution.

Actual Results

The corresponding curl call gives some more output. The interesting part:

curl -X POST -H  'User-Agent: python-requests/2.23.0' -H  'Accept-Encoding: gzip, deflate' -H  'Accept: */*' -H  'Connection: keep-alive' -H  'content-type: application/json' -H  'Content-Length: 70' --data-binary '{"action": "core.local", "parameters": {"cmd": "uname"}, "user": null}' http://127.0.0.1:9101/v1/executions

# -------- begin 139695680141744 response ----------
{
    "faultstring": "datetime.datetime(2020, 4, 13, 23, 12, 56, 492255, tzinfo=tzutc()) is not JSON serializable"
}
# -------- end 139695680141744 response ------------

ERROR: 500 Server Error: Internal Server Error
MESSAGE: datetime.datetime(2020, 4, 13, 23, 12, 56, 492255, tzinfo=tzutc()) is not JSON serializable for url: http://127.0.0.1:9101/v1/executions

CLI settings:
----------------
Config file path: /home/marcel/.st2/config
Client settings:
----------------
ST2_BASE_URL: http://127.0.0.1
ST2_AUTH_URL: http://127.0.0.1:9100
ST2_API_URL: http://127.0.0.1:9101/v1
ST2_STREAM_URL: http://127.0.0.1:9102/v1
ST2_AUTH_TOKEN: None

Proxy settings:
---------------
HTTP_PROXY: 
HTTPS_PROXY: 

Traceback (most recent call last):
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/shell.py", line 407, in run
    func(args)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/commands/resource.py", line 47, in decorate
    return func(*args, **kwargs)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/commands/action.py", line 263, in run_and_print
    execution = self.run(args, **kwargs)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/commands/resource.py", line 47, in decorate
    return func(*args, **kwargs)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/commands/action.py", line 1015, in run
    execution = action_exec_mgr.create(execution, **kwargs)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/models/core.py", line 41, in decorate
    return func(*args, **kwargs)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/models/core.py", line 307, in create
    self.handle_error(response)
  File "/home/marcel/Sources/gitlab.winem/st2/st2client/st2client/models/core.py", line 167, in handle_error
    response.raise_for_status()
  File "/home/marcel/Sources/gitlab.winem/st2/venv3.6/lib/python3.6/site-packages/requests/models.py", line 941, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 500 Server Error: Internal Server Error
MESSAGE: datetime.datetime(2020, 4, 13, 23, 12, 56, 492255, tzinfo=tzutc()) is not JSON serializable for url: http://127.0.0.1:9101/v1/executions

Let me know if anything else is needed.

Thanks in advance!

[blag]

Possibly related to #4892.

If so, the fix for this would be to check for datetime.datetime objects and serialize them to strings.

The DjangoJSONEncoder would be a good reference for implementing this. It also includes serializations for other objects as well:

• datetime.date
• datetime.time
• datetime.timedelta
• decimal.Decimal
• uuid.UUID

[nmaludy]

Shouldn't the CLI command be?

st2 run core.local cmd=uname

[nmaludy]

The command you gave worked for my on el8 st2vagrant box (couldn't reproduce):

$ RELEASE="unstable" BOX="centos/8" vagrant up
$ vagrant ssh
$ sudo su -
$ st2 run core.local uname
.
id: 5e9509a17ba42a8d951b7516
action.ref: core.local
context.user: st2admin
parameters: 
  cmd: uname
status: succeeded
start_timestamp: Tue, 14 Apr 2020 00:53:53 UTC
end_timestamp: Tue, 14 Apr 2020 00:53:53 UTC
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: Linux
  succeeded: true

[winem]

Shouldn't the CLI command be?

st2 run core.local cmd=uname

Just tried that with the same result. I will follow up on this topic tomorrow.

[nmaludy]

@winem worked for me on Ubuntu 18.04 too:

$ RELEASE="unstable" BOX="generic/ubuntu1804" vagrant up
$ vagrant ssh
$ sudo su -
# st2 run core.local uname
.
id: 5e95119c5b087dd05aedfdcd
action.ref: core.local
context.user: st2admin
parameters: 
  cmd: uname
status: succeeded
start_timestamp: Tue, 14 Apr 2020 01:27:56 UTC
end_timestamp: Tue, 14 Apr 2020 01:27:56 UTC
result: 
  failed: false
  return_code: 0
  stderr: ''
  stdout: Linux
  succeeded: true

[winem]

Thanks for testing.

It seems indeed to be an issue on my local workstation. I am still not entirely sure about the root cause and thought that I'll be mostly independent from OS packages when using the virtual-env but something seems to have some impact here. Investigation is still ongoing and I'll update/close the issue accordingly as soon as I have any results.

[arm4b]

$ RELEASE="unstable" BOX="generic/ubuntu1804" vagrant up

@nmaludy I think the diff here is that @winem is trying to run st2 from sources and not from (unstable) packages.

[winem]

This evening I setup a new instance with Ubuntu 18.04.3 at DigitalOcean from scratch to ensure that it's not an issue with any local configuration. It's still reproducable so I spend some time to make the repro as straight-forward as possible.

This is the full repro:

1. user-data file which should work on AWS images as well:
   WARNING: The docker-compose file will expose the ports of the services. Make sure to have a firewall or security group being in place for this instance before running it!

(Note: the compose and env files are a clone from the st2-docker setup + the exposed ports which works fine.)

#!/usr/bin/env bash
apt update
apt install -y python3-pip python3-virtualenv python3-dev python-pip python-virtualenv python-dev gcc git make screen libffi-dev libssl-dev 

apt install -y apt-transport-https ca-certificates curl software-properties-common
curl -fsSL https://download.docker.com/linux/ubuntu/gpg | sudo apt-key add -
sudo add-apt-repository "deb [arch=amd64] https://download.docker.com/linux/ubuntu bionic stable"
apt update
apt install -y docker-ce

sudo curl -L "https://github.com/docker/compose/releases/download/1.25.5/docker-compose-$(uname -s)-$(uname -m)" -o /usr/local/bin/docker-compose
sudo chmod +x /usr/local/bin/docker-compose

mkdir -p /opt/stackstorm-external-services/conf

cd /opt/stackstorm-external-services
cat > docker-compose.yml << EOC
version: '3'

services:
### External Services

  mongo:
    image: mongo:3.4
    env_file:
      - conf/mongo.env
    networks:
      - public
    ports:
      - 27017:27017
    volumes:
      - mongo-volume:/data/db
      - mongo-configdb-volume:/data/configdb
    dns_search: .
  rabbitmq:
    image: rabbitmq:3.6-management
    env_file:
      - conf/rabbitmq.env
    networks:
      - public
    ports:
      - 4369:4369
      - 5671-5672:5671-5672
      - 15671-15672:15671-15672
      - 25672:25672
    volumes:
      - rabbitmq-volume:/var/lib/rabbitmq
    dns_search: .
  postgres:
    image: postgres:9.6
    env_file:
      - conf/postgres.env
    networks:
      - public
    ports:
      - 5432:5432
    volumes:
      - postgres-volume:/var/lib/postgresql/data
    dns_search: .
  redis:
    image: redis:4.0
    env_file:
      - conf/redis.env
    networks:
      - public
    ports:
      - 6379:6379
    volumes:
      - redis-volume:/data
    dns_search: .
    command: [
      "bash", "-c",
      '
       docker-entrypoint.sh
       --requirepass "$$REDIS_PASSWORD"
      '
    ]

volumes:
  mongo-volume:
  mongo-configdb-volume:
  postgres-volume:
  rabbitmq-volume:
  redis-volume:

networks:
  public:
    driver: bridge
  private:
    driver: bridge
EOC

cat > conf/mongo.env << EOM
MONGO_HOST=mongo
MONGO_PORT=27017
#MONGO_DB=
#MONGO_USER=
#MONGO_PASS=
EOM

cat > conf/postgres.env << EOP
POSTGRES_USER=mistral-user
POSTGRES_PASSWORD=ekNuwA4x+D78k6wGJ8vKW2zT
POSTGRES_HOST=postgres
POSTGRES_PORT=5432
POSTGRES_DB=mistral
EOP

cat > conf/rabbitmq.env << EOR
RABBITMQ_DEFAULT_USER=guest
RABBITMQ_DEFAULT_PASS=guest
RABBITMQ_HOST=rabbitmq
RABBITMQ_PORT=5672
EOR

cat > conf/redis.env << EOKV
REDIS_PASSWORD=6i7bAhAiH2Nt30vDsmQfpxVT
REDIS_HOST=redis
REDIS_PORT=6379
EOKV

cd /opt/
git clone https://github.com/StackStorm/st2.git
cd st2
git submodule update --init --recursive
make requirements

useradd -d /home/stanley stanley
mkdir -p /home/stanley/.ssh
chown -R stanley. /home/stanley
runuser -l stanley -c "ssh-keygen -f /home/stanley/.ssh/stanley_rsa -t rsa -b 4096 -C 'stanley@stackstorm.com' -N ''"

cd /opt/stackstorm-external-services/
docker-compose up -d

2. after logging in as root:
   2.1. update the requirements from ujson==1.35 to ujson==2.0.0 to avoid this error when starting Stackstorm:

ImportError: /home/marcel/Sources/gitlab.winem/st2/virtualenv/lib/python2.7/site-packages/ujson.so: undefined symbol: Buffer_AppendShortHexUnchecked

(See also: ultrajson/ultrajson#346)

cd /opt/st2
sed -i 's/ujson==1.35/ujson==2.0.0/' fixed-requirements.txt
sed -i 's/ujson==1.35/ujson==2.0.0/' requirements.txt 
sed -i 's/ujson==1.35/ujson==2.0.0/' st2common/requirements.txt 

2.2. Install the new dependency and run stackstorm:

source virtualenv/bin/activate
pip install -r requirements.txt

# verify that ujson 2.0.0 is installed
pip show ujson

# run stackstorm
./tools/launchdev.sh startclean

2.3. Install stackstorm CLI

cd st2client
python setup.py develop

2.4. Run st2-commands:

# these work fine 
st2 --version
st2 action list
st2 action get core.local

# these one are examples that fail
st2 run core.local uname
st2 action execute core.local date
st2 run core.echo message="foobar"

Example error message:

(virtualenv) root@st2-4908-03:/opt/st2/st2client# st2 run core.local cmd=date
ERROR: 500 Server Error: Internal Server Error
MESSAGE: datetime.datetime(2020, 4, 15, 0, 2, 54, 70199, tzinfo=tzutc()) is not JSON serializable for url: http://127.0.0.1:9101/v1/executions

The error is always the same.

---

I also tried it with the master at commit dfd85453ba40fe16d41999fa69cab2d1e8f877f7 which is the last one before the mentioned MR got merged. I'll follow up on @blag 's idea tomorrow.

Please, let me know if there is anything else to try or provide.

[winem]

Quick braindump:

I just set up another dev env from source with the current master (commit: 397e2f7) and I still get the undefined symbol: Buffer_AppendShortHexUnchecked ujson related error.

[winem]

Ok, now I (think to) know the culprit:

The ActionExecutionDB (st2/st2common/st2common/models/db/execution.py) object contains an object log which looks like this:

log=[{'status': 'requested', 'timestamp': datetime.datetime(2020, 8, 7, 22, 21, 4, 685383, tzinfo=tzutc())}]

The timestamp here is not serializable. It's almost 1 a.m. over here, so I'll sleep over it and try to work on a fix tomorrow.

My current idea is to iterate over the fields in the log object (either when it's created or directly in the ActionExecutionDB) and have some simple function like if there is not already a validator that handles this case in the common utils:

def serializeDatetimeObjectToJson(object):
  if isinstance(object, (datetime.date, datetime.datetime)):
    return object.isoformat()

But there might be more elegant ideas. So we'll see...

And as always, any input is welcome!