Shortshare and shortfees not logging when complete

Technical Help
#1

I have a monitoring solution that parses the flightlog logfiles and gives alerts etc.

I have recently been having issues with the fundamental service not always logging. The collection of short shares and short fees are scheduled daily using the countdown crontab and trigger fine, but they don't always log a 'INFO: Saved' Message.

The following shows up in the logs:

2020-01-12 23:15:03 quantrocket.fundamental: INFO Collecting australia shortable shares from 2020-01-01 
to present
2020-01-12 23:45:03 quantrocket.fundamental: INFO Collecting australia borrow fees from 2020-01-01 to 
present

But no 'INFO: Saved' message, it is only then in the morning when when i get alerts that nothing was saved. I run the command manually and only then the 'INFO: Saved' messages appear like:

2020-01-13 10:21:06 quantrocket.fundamental: INFO Collecting australia borrow fees from 2020-01-01 to 
present
2020-01-13 10:21:07 quantrocket.fundamental: INFO Saved 1248 total borrow fees records to 
quantrocket.fundamental.stockloan.fees.sqlite
2020-01-13 10:23:37 quantrocket.fundamental: INFO Collecting australia shortable shares from 2020-01-01 
to present
2020-01-13 10:23:37 quantrocket.fundamental: INFO Saved 391 total shortable shares records to 
quantrocket.fundamental.stockloan.shares.sqlite
#2

I'm sorry, my only advice is to check the detailed logs for clues.

#3

Here is a detailed log for when it successfully logs:

2020-01-13 10:23:37 AEDT| <14>1 2020-01-12T23:23:37Z af3c0cfe74d4 quantrocket_fundamental_1 3420 - - Collecting and loading australia shortable shares for 2020-01
2020-01-13 10:23:37 AEDT| <14>1 2020-01-12T23:23:37Z 41e5823bee81 quantrocket_flightlog_1 3760 - - 2020-01-13 10:23:37 quantrocket.fundamental: INFO Collecting australia shortable shares from 2020-01-01 to present
2020-01-13 10:23:37 AEDT| <11>1 2020-01-12T23:23:37Z 41e5823bee81 quantrocket_flightlog_1 3760 - - Mon Jan 13 10:23:37 2020 - [emperor] vassal /etc/uwsgi/uwsgi_httpreceive.ini is now loyal
2020-01-13 10:23:37 AEDT| <14>1 2020-01-12T23:23:37Z d8b62a1bac75 quantrocket_houston_1 13801 - - 172.18.0.15 - - [12/Jan/2020:23:23:37 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
2020-01-13 10:23:37 AEDT| <14>1 2020-01-12T23:23:37Z 41e5823bee81 quantrocket_flightlog_1 3760 - - announcing my loyalty to the Emperor...
2020-01-13 10:23:37 AEDT| <14>1 2020-01-12T23:23:37Z 41e5823bee81 quantrocket_flightlog_1 3760 - - 2020-01-13 10:23:37 quantrocket.fundamental: INFO Saved 391 total shortable shares records to quantrocket.fundamental.stockloan.shares.sqlite

Here is a detailed log for when it doesn't log:

2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z af3c0cfe74d4 quantrocket_fundamental_1 3420 - - Collecting and loading australia shortable shares for 2020-01
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - 2020-01-19 02:30:11 quantrocket.fundamental: INFO Collecting australia shortable shares from 2020-01-01 to present
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z d8b62a1bac75 quantrocket_houston_1 13801 - - 172.18.0.15 - - [18/Jan/2020:15:30:11 +0000] "POST /flightlog/handler HTTP/1.1" 200 5 "-" "-"
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - announcing my loyalty to the Emperor...
2020-01-19 02:30:11 AEDT| <11>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - Sun Jan 19 02:30:11 2020 - [emperor] vassal /etc/uwsgi/uwsgi_httpreceive.ini is now loyal
2020-01-19 02:30:11 AEDT| <11>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - Sun Jan 19 02:30:11 2020 - [emperor] reload the uwsgi instance /etc/uwsgi/uwsgi_httpreceive.ini
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - Sun Jan 19 02:30:11 2020 - received message 1 from emperor
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - gateway "uWSGI http 1" has been buried (pid: 23344)
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - ...gracefully killing workers...
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - Gracefully killing worker 1 (pid: 23342)...
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - [deadlock-detector] a process holding a robust mutex died. recovering...
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - pthread_cancel()
2020-01-19 02:30:11 AEDT| <14>1 2020-01-18T15:30:11Z 41e5823bee81 quantrocket_flightlog_1 11950 - - : Success [core/uwsgi.c line 1206]
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - worker 1 buried after 1 seconds
2020-01-19 02:30:12 AEDT| <11>1 2020-01-18T15:30:12Z d8b62a1bac75 quantrocket_houston_1 13801 - - 2020/01/18 15:30:12 [error] 18#18: *167653 recv() failed (104: Connection reset by peer) while reading response header from upstream, client: 172.18.0.15, server: , request: "POST /flightlog/handler HTTP/1.1", upstream: "http://172.18.0.20:9020/logs", host: "houston"
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - binary reloading uWSGI...
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - chdir() to /
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - closing all non-uwsgi socket fds > 2 (max_fd = 1048576)...
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - found fd 9 mapped to socket 0 (127.0.0.1:41371)
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z d8b62a1bac75 quantrocket_houston_1 13801 - - 172.18.0.15 - - [18/Jan/2020:15:30:12 +0000] "POST /flightlog/handler HTTP/1.1" 502 0 "-" "-"
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - xr��� xr��� p�tU p�tU *** has_emperor mode detected (fd: 6) ***
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - [uWSGI] getting INI configuration from /etc/uwsgi/uwsgi_httpreceive.ini
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z 41e5823bee81 quantrocket_flightlog_1 11950 - - [uWSGI] getting INI configuration from /etc/uwsgi/base.ini
2020-01-19 02:30:12 AEDT| <14>1 2020-01-18T15:30:12Z af3c0cfe74d4 quantrocket_fundamental_1 3420 - - recycling mule after collecting shortable shares
2020-01-19 02:30:13 AEDT| <14>1 2020-01-18T15:30:13Z af3c0cfe74d4 quantrocket_fundamental_1 3420 - - OOOPS mule 2 (pid: 171) crippled...trying respawn...
2020-01-19 02:30:13 AEDT| <14>1 2020-01-18T15:30:13Z af3c0cfe74d4 quantrocket_fundamental_1 3420 - - spawned uWSGI mule 2 (pid: 174)

It seems to always log correctly when I run it manually after it fails, but never the first time.

#4

I don't see any subscription under your email address. Are you subscribed under another email? I'm confused about who I'm helping.

#5

This user is working with me, thanks.

#6

What the "bad" logs are showing is that the data collection is running fine but the flightlog worker is getting killed (gracefully killing workers…) so when the fundamental service logs completion, there is no one to receive the message ( (104: Connection reset by peer) while reading response header from upstream). I don't have an answer for why flightlog is getting killed there. I would either try to pinpoint the circumstances under which it gets killed, or re-create flightlog, or try to use a different technique to determine completion such as querying the data directly.

#7

Recreating the flightlog container seems to have fixed the problems as it is now logging correctly.

Thanks.