search

Seafood-Globalization-Lab / ARTIS-API

0 stars 0 forks source link

500 Error Requesting Main ARTIS snet Data #8

Open ahmattox opened 1 week ago

ahmattox commented 1 week ago

Request:

GET /snet/query?cols_wanted=year&weight_type=live_weight_t&start_year=2015&end_year=2020&search_criteria=0 HTTP/1.1
X-API-KEY: XXXX
Host: artis-a845c2b00aea.herokuapp.com
Connection: close
User-Agent: RapidAPI/4.2.4 (Macintosh; OS X/14.5.0) GCDHTTPRequest

Response:

HTTP/1.1 500 Internal Server Error
Server: Cowboy
Report-To: {"group":"heroku-nel","max_age":3600,"endpoints":[{"url":"https://nel.heroku.com/reports?ts=1719499645&sid=e11707d5-02a7-43ef-b45e-2cf4d2036f7d&s=MaIT%2BsoEpmofvyMrqg26SIB4hYWRRsteGiClkpg33UU%3D"}]}
Reporting-Endpoints: heroku-nel=https://nel.heroku.com/reports?ts=1719499645&sid=e11707d5-02a7-43ef-b45e-2cf4d2036f7d&s=MaIT%2BsoEpmofvyMrqg26SIB4hYWRRsteGiClkpg33UU%3D
Nel: {"report_to":"heroku-nel","max_age":3600,"success_fraction":0.005,"failure_fraction":0.05,"response_headers":["Via"]}
Connection: close
X-Powered-By: Express
Content-Type: text/plain; charset=utf-8
Content-Length: 21
Etag: W/"15-/6VXivhc2MKdLfIkLcUE47K6aH0"
Date: Thu, 27 Jun 2024 14:47:25 GMT
Via: 1.1 vegur

Internal Server Error

Server log sample:

2024-06-27T14:47:25.054429+00:00 heroku[router]: at=info method=GET path="/snet/query?cols_wanted=year&weight_type=live_weight_t&start_year=2015&end_year=2020&search_criteria=0" host=artis-a845c2b00aea.herokuapp.com request_id=2919ee82-a6b8-404b-96cf-f494403ad775 fwd="73.173.92.17" dyno=web.1 connect=0ms service=19ms status=500 bytes=241 protocol=https
2024-06-27T14:47:32.721064+00:00 app[web.1]: ReplyError: OOM command not allowed when used memory > 'maxmemory'. script: 135a97538ee393c145e6d418b575b3aa1799c691, on @user_script:191.
2024-06-27T14:47:32.721107+00:00 app[web.1]: at parseError (/app/node_modules/redis-parser/lib/parser.js:179:12)
2024-06-27T14:47:32.721108+00:00 app[web.1]: at parseType (/app/node_modules/redis-parser/lib/parser.js:302:14) {
2024-06-27T14:47:32.721108+00:00 app[web.1]: command: {
2024-06-27T14:47:32.721109+00:00 app[web.1]: name: 'evalsha',
2024-06-27T14:47:32.721109+00:00 app[web.1]: args: [
2024-06-27T14:47:32.721109+00:00 app[web.1]: '135a97538ee393c145e6d418b575b3aa1799c691',
2024-06-27T14:47:32.721110+00:00 app[web.1]: '11',
2024-06-27T14:47:32.721110+00:00 app[web.1]: 'bull:pgJobsQ:wait',
2024-06-27T14:47:32.721110+00:00 app[web.1]: 'bull:pgJobsQ:active',
2024-06-27T14:47:32.721111+00:00 app[web.1]: 'bull:pgJobsQ:prioritized',
2024-06-27T14:47:32.721111+00:00 app[web.1]: 'bull:pgJobsQ:events',
2024-06-27T14:47:32.721111+00:00 app[web.1]: 'bull:pgJobsQ:stalled',
2024-06-27T14:47:32.721111+00:00 app[web.1]: 'bull:pgJobsQ:limiter',
2024-06-27T14:47:32.721111+00:00 app[web.1]: 'bull:pgJobsQ:delayed',
2024-06-27T14:47:32.721112+00:00 app[web.1]: 'bull:pgJobsQ:paused',
2024-06-27T14:47:32.721112+00:00 app[web.1]: 'bull:pgJobsQ:meta',
2024-06-27T14:47:32.721112+00:00 app[web.1]: 'bull:pgJobsQ:pc',
2024-06-27T14:47:32.721112+00:00 app[web.1]: 'bull:pgJobsQ:marker',
2024-06-27T14:47:32.721113+00:00 app[web.1]: 'bull:pgJobsQ:',
2024-06-27T14:47:32.721113+00:00 app[web.1]: '1719499652719',
2024-06-27T14:47:32.721113+00:00 app[web.1]: <Buffer de 00 04 a5 74 6f 6b 65 6e d9 2a 62 65 65 66 63 64 34 32 2d 62 37 61 33 2d 34 35 61 62 2d 38 33 35 61 2d 64 32 66 39 33 31 38 37 32 38 30 66 3a 31 33 ... 34 more bytes>
2024-06-27T14:47:32.721113+00:00 app[web.1]: ]
2024-06-27T14:47:32.721114+00:00 app[web.1]: }
...
ahmattox commented 1 week ago

These are no longer returning 500 errors, but the jobs are now failing. The job continues to be listed as active but I see a memory error in the server logs:

2024-07-02T13:39:41.000000+00:00 app[postgres.3587640]: [GOLD] [32-1]  sql_error_code = 00000 time_ms = "2024-07-02 13:39:41.414 UTC" pid="1571761" proc_start_time="2024-07-02 13:37:27 UTC" session_id="66840297.17fbb1" vtid="6/0" tid="0" log_line="6" database="dekn24t9v2f154" connection_source="54.227.81.12(35686)" user="uedg5kjabjsbg0" application_name="[unknown]" LOG:  duration: 134364.382 ms  statement: SELECT exporter_iso3c, importer_iso3c, source_country_iso3c, dom_source, hs6, sciname, habitat, method, year, SUM(product_weight_t) AS product_weight_t FROM snet WHERE year >= 2010 AND year <= 2020 AND ((hs_version = 'HS96' AND year >= 1996 AND year <= 2003) OR (hs_version = 'HS02' AND year >= 2004 AND year <= 2009) OR (hs_version = 'HS07' AND year >= 2010 AND year <= 2012) OR (hs_version = 'HS12' AND year >= 2013 AND year <= 2020)) AND exporter_iso3c in ('USA') AND method in ('capture') GROUP BY exporter_iso3c, importer_iso3c, source_country_iso3c,
2024-07-02T13:39:41.000000+00:00 app[postgres.3587640]: [GOLD] [32-2]  dom_source, hs6, sciname, habitat, method, year
2024-07-02T13:39:42.946769+00:00 app[web.1]: 
2024-07-02T13:39:42.946851+00:00 app[web.1]: <--- Last few GCs --->
2024-07-02T13:39:42.946851+00:00 app[web.1]: 
2024-07-02T13:39:42.946852+00:00 app[web.1]: [21:0x4df7cb0] 65415147 ms: Mark-sweep (reduce) 252.8 (258.1) -> 252.0 (258.6) MB, 246.2 / 0.0 ms  (average mu = 0.800, current mu = 0.248) allocation failure scavenge might not succeed
2024-07-02T13:39:42.946853+00:00 app[web.1]: [21:0x4df7cb0] 65415389 ms: Mark-sweep (reduce) 253.3 (258.6) -> 252.4 (259.1) MB, 235.2 / 0.0 ms  (average mu = 0.648, current mu = 0.029) allocation failure scavenge might not succeed
2024-07-02T13:39:42.946853+00:00 app[web.1]: 
2024-07-02T13:39:42.946853+00:00 app[web.1]: 
2024-07-02T13:39:42.946854+00:00 app[web.1]: <--- JS stacktrace --->
2024-07-02T13:39:42.946854+00:00 app[web.1]: 
2024-07-02T13:39:42.948982+00:00 app[web.1]: FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
2024-07-02T13:39:42.974917+00:00 app[web.1]: 1: 0xb06730 node::Abort() [node]
2024-07-02T13:39:42.975302+00:00 app[web.1]: 2: 0xa1b6d0  [node]
2024-07-02T13:39:42.977627+00:00 app[web.1]: 3: 0xce1dd0 v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node]
2024-07-02T13:39:42.979104+00:00 app[web.1]: 4: 0xce2177 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node]
2024-07-02T13:39:42.979601+00:00 app[web.1]: 5: 0xe997e5  [node]
2024-07-02T13:39:42.980117+00:00 app[web.1]: 6: 0xea94ad v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node]
2024-07-02T13:39:42.981668+00:00 app[web.1]: 7: 0xeac1ae v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [node]
2024-07-02T13:39:42.986326+00:00 app[web.1]: 8: 0xe6d422 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [node]
2024-07-02T13:39:42.989272+00:00 app[web.1]: 9: 0xe65a34 v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [node]
2024-07-02T13:39:42.991729+00:00 app[web.1]: 10: 0xe67740 v8::internal::FactoryBase<v8::internal::Factory>::NewRawOneByteString(int, v8::internal::AllocationType) [node]
2024-07-02T13:39:42.994179+00:00 app[web.1]: 11: 0x12430e5 v8::internal::IncrementalStringBuilder::Extend() [node]
2024-07-02T13:39:42.995962+00:00 app[web.1]: 12: 0xf91018 v8::internal::JsonStringifier::SerializeDouble(double) [node]
2024-07-02T13:39:42.998875+00:00 app[web.1]: 13: 0xf93b77 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<true>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
2024-07-02T13:39:43.001388+00:00 app[web.1]: 14: 0xf977f1 v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
2024-07-02T13:39:43.001911+00:00 app[web.1]: 15: 0xf9812d v8::internal::JsonStringifier::Result v8::internal::JsonStringifier::Serialize_<false>(v8::internal::Handle<v8::internal::Object>, bool, v8::internal::Handle<v8::internal::Object>) [node]
2024-07-02T13:39:43.003527+00:00 app[web.1]: 16: 0xf9910f v8::internal::JsonStringify(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>) [node]
2024-07-02T13:39:43.005907+00:00 app[web.1]: 17: 0xd64037 v8::internal::Builtin_JsonStringify(int, unsigned long*, v8::internal::Isolate*) [node]
2024-07-02T13:39:43.006556+00:00 app[web.1]: 18: 0x15da1b9  [node]
2024-07-02T13:39:43.032183+00:00 app[web.1]: Aborted
2024-07-02T13:39:43.198273+00:00 app[web.1]: npm notice
2024-07-02T13:39:43.199700+00:00 app[web.1]: npm notice New minor version of npm available! 10.5.2 -> 10.8.1
2024-07-02T13:39:43.199807+00:00 app[web.1]: npm notice Changelog: <https://github.com/npm/cli/releases/tag/v10.8.1>
2024-07-02T13:39:43.200722+00:00 app[web.1]: npm notice Run `npm install -g npm@10.8.1` to update!
2024-07-02T13:39:43.200796+00:00 app[web.1]: npm notice
2024-07-02T13:39:43.324838+00:00 heroku[web.1]: Process exited with status 134
2024-07-02T13:39:43.353470+00:00 heroku[web.1]: State changed from up to crashed
2024-07-02T13:39:43.356272+00:00 heroku[web.1]: State changed from crashed to starting
2024-07-02T13:39:47.963815+00:00 heroku[web.1]: Starting process with command `npm start`
2024-07-02T13:39:49.360840+00:00 app[web.1]: 
2024-07-02T13:39:49.360879+00:00 app[web.1]: > artis-api@1.0.0 start
2024-07-02T13:39:49.360879+00:00 app[web.1]: > node dist/index.js
2024-07-02T13:39:49.360880+00:00 app[web.1]: 
2024-07-02T13:38:45.000000+00:00 app[heroku-postgres]: source=HEROKU_POSTGRESQL_GOLD addon=postgresql-angular-82736 sample#service-available=1 sample#current_transaction=780 sample#db_size=22957011759bytes sample#tables=5 sample#active-connections=16 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99467 sample#table-cache-hit-rate=0.16131 sample#load-avg-1m=0.88 sample#load-avg-5m=0.345 sample#load-avg-15m=0.13 sample#read-iops=2750.6 sample#write-iops=0.02381 sample#tmp-disk-used=610611200 sample#tmp-disk-available=72368181248 sample#memory-total=3944484kB sample#memory-free=40140kB sample#memory-cached=3408028kB sample#memory-postgres=8272kB sample#wal-percentage-used=0.06451963698416063 sample#rollback-from=2024-06-28T13:39UTC

This is after making this request for data for one country. This request did work reasonably quickly before switching to the async version of the API:

GET /snet/query/?cols_wanted=exporter_iso3c,importer_iso3c,source_country_iso3c,dom_source,hs6,sciname,habitat,method,year&weight_type=product_weight_t&start_year=2010&end_year=2020&search_criteria=1&exporter_iso3c=USA&method=capture HTTP/1.1
X-API-KEY: XXX
Host: artis-a845c2b00aea.herokuapp.com
Connection: close
User-Agent: RapidAPI/4.2.4 (Macintosh; OS X/14.5.0) GCDHTTPRequest