InfluxDB does not start

arturo · March 18, 2022, 8:31am

Hello,

I’m trying the influxdb on debian armhf system. Generally it seems pretty good, I can write and read to the database.
But on reboots I get some error and the database does not start any more.

What is the reason for this errors and how can I prevent this?
I just want to start the influx cleanly on every reboot.

influx_inspect did not report any errors on the database.

Below the log outputs on start:

 8888888           .d888 888                   8888888b.  888888b.
   888            d88P"  888                   888  "Y88b 888  "88b
   888            888    888                   888    888 888  .88P
   888   88888b.  888888 888 888  888 888  888 888    888 8888888K.
   888   888 "88b 888    888 888  888  Y8bd8P' 888    888 888  "Y88b
   888   888  888 888    888 888  888   X88K   888    888 888    888
   888   888  888 888    888 Y88b 888 .d8""8b. 888  .d88P 888   d88P
 8888888 888  888 888    888  "Y88888 888  888 8888888P"  8888888P"

2022-03-18T08:28:20.660998Z     info    InfluxDB starting       {"log_id": "0_J26sBG000", "version": "1.6.4", "branch": "unknown", "commit": "unknown"}
2022-03-18T08:28:20.667689Z     info    Go runtime      {"log_id": "0_J26sBG000", "version": "go1.11.6", "maxprocs": 1}
2022-03-18T08:28:20.782133Z     info    Using data dir  {"log_id": "0_J26sBG000", "service": "store", "path": "/var/lib/influxdb/data"}
2022-03-18T08:28:20.785768Z     info    Compaction settings     {"log_id": "0_J26sBG000", "service": "store", "max_concurrent_compactions": 1, "throughput_bytes_per_second": 50331648, "throughput_burst_bytes": 50331648}
2022-03-18T08:28:20.790909Z     info    Open store (start)      {"log_id": "0_J26sBG000", "service": "store", "trace_id": "0_J26siW000", "op_name": "tsdb_open", "op_event": "start"}
2022-03-18T08:28:20.838005Z     info    tsm1 WAL starting       {"log_id": "0_J26sBG000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T08:28:20.843556Z     info    tsm1 WAL writing        {"log_id": "0_J26sBG000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2"}
2022-03-18T08:28:20.854928Z     info    Opened file     {"log_id": "0_J26sBG000", "engine": "tsm1", "service": "filestore", "path": "/var/lib/influxdb/data/artxdb/autogen/2/000000001-000000001.tsm", "id": 0, "duration": "1.457ms"}
2022-03-18T08:28:20.863099Z     info    Reloaded WAL cache      {"log_id": "0_J26sBG000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/2", "duration": "1.815ms"}
2022-03-18T08:28:20.902706Z     info    Meta data index for shard loaded        {"log_id": "0_J26sBG000", "engine": "tsm1", "id": 2, "duration": "36.465ms"}
2022-03-18T08:28:20.907656Z     info    Opened shard    {"log_id": "0_J26sBG000", "service": "store", "trace_id": "0_J26siW000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "78.566ms"}
2022-03-18T08:28:20.920332Z     info    tsm1 WAL starting       {"log_id": "0_J26sBG000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T08:28:20.921424Z     info    tsm1 WAL writing        {"log_id": "0_J26sBG000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/1"}
2022-03-18T08:28:20.933414Z     info    Reloaded WAL cache      {"log_id": "0_J26sBG000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/1", "duration": "1.457ms"}
2022-03-18T08:28:20.965720Z     info    Meta data index for shard loaded        {"log_id": "0_J26sBG000", "engine": "tsm1", "id": 1, "duration": "31.212ms"}
2022-03-18T08:28:20.972046Z     info    Opened shard    {"log_id": "0_J26sBG000", "service": "store", "trace_id": "0_J26siW000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/1", "duration": "59.307ms"}
2022-03-18T08:28:20.978798Z     info    Open store (end)        {"log_id": "0_J26sBG000", "service": "store", "trace_id": "0_J26siW000", "op_name": "tsdb_open", "op_event": "end", "op_elapsed": "187.937ms"}
run: open server: open tsdb store: function not implemented

I don’t know if this is also of concern …
In short before I shut down the influxd, I observed also some error entry in outputs:

2022-03-18T08:23:45.692594Z     info    Compacting cache        {"log_id": "0_J1Gdcl000", "engine": "tsm1", "path": "/var/lib/influxdb/data/artxdb/autogen/2"}
2022-03-18T08:23:45.705489Z     info    Cache snapshot (start)  {"log_id": "0_J1Gdcl000", "engine": "tsm1", "trace_id": "0_J1r5AG000", "op_name": "tsm1_cache_snapshot", "op_event": "start"}
2022-03-18T08:23:45.735391Z     info    Snapshot for path deduplicated  {"log_id": "0_J1Gdcl000", "engine": "tsm1", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "3.682ms"}
2022-03-18T08:23:45.849272Z     info    Removing WAL file       {"log_id": "0_J1Gdcl000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2/_00001.wal"}
2022-03-18T08:23:45.868367Z     info    Snapshot for path written       {"log_id": "0_J1Gdcl000", "engine": "tsm1", "trace_id": "0_J1r5AG000", "op_name": "tsm1_cache_snapshot", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "163.179ms"}
2022-03-18T08:23:45.872310Z     info    Cache snapshot (end)    {"log_id": "0_J1Gdcl000", "engine": "tsm1", "trace_id": "0_J1r5AG000", "op_name": "tsm1_cache_snapshot", "op_event": "end", "op_elapsed": "166.923ms"}
2022-03-18T08:23:52.791407Z     warn    Error while freeing cold shard resources        {"log_id": "0_J1Gdcl000", "service": "store", "error": "function not implemented", "db_shard_id": 2}

Thank you for your help!

Jay_Clifford · March 18, 2022, 9:47am

Hi @arturo,
It appears you are using quite an old version of InfluxDB. I would advice either using the latest InfluxDB 1.X build (1.8.10) or consider to start using InfluxDB 2.X .

arturo · March 18, 2022, 12:22pm

Hi Jay_Clifford,

yeah, this logs are wit the 1.6.4 Version directly from the debian repo.
I also tested this with the 1.8.10 version that I directly downloaded form influxdata.com page.
But there is the same behavior. I have no Idea what is the reason and where to look for solutions.
Every time there is this message “run: open server: open tsdb store: function not implemented”

This are the output form 1.8.10 influxd (I have armhf system and did not find any binary of 2.x version for armhf)

 8888888           .d888 888                   8888888b.  888888b.
   888            d88P"  888                   888  "Y88b 888  "88b
   888            888    888                   888    888 888  .88P
   888   88888b.  888888 888 888  888 888  888 888    888 8888888K.
   888   888 "88b 888    888 888  888  Y8bd8P' 888    888 888  "Y88b
   888   888  888 888    888 888  888   X88K   888    888 888    888
   888   888  888 888    888 Y88b 888 .d8""8b. 888  .d88P 888   d88P
 8888888 888  888 888    888  "Y88888 888  888 8888888P"  8888888P"

2022-03-18T12:40:33.314533Z     info    InfluxDB starting       {"log_id": "0_JGYV3W000", "version": "1.8.10", "branch": "1.8", "commit": "688e697c51fd"}
2022-03-18T12:40:33.326252Z     info    Go runtime      {"log_id": "0_JGYV3W000", "version": "go1.13.8", "maxprocs": 1}
2022-03-18T12:40:33.447309Z     info    Using data dir  {"log_id": "0_JGYV3W000", "service": "store", "path": "/var/lib/influxdb/data"}
2022-03-18T12:40:33.464359Z     info    Compaction settings     {"log_id": "0_JGYV3W000", "service": "store", "max_concurrent_compactions": 1, "throughput_bytes_per_second": 50331648, "throughput_bytes_per_second_burst": 50331648}
2022-03-18T12:40:33.484305Z     info    Open store (start)      {"log_id": "0_JGYV3W000", "service": "store", "trace_id": "0_JGYVnW000", "op_name": "tsdb_open", "op_event": "start"}
2022-03-18T12:40:33.697374Z     info    tsm1 WAL starting       {"log_id": "0_JGYV3W000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T12:40:33.713324Z     info    tsm1 WAL writing        {"log_id": "0_JGYV3W000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/1"}
2022-03-18T12:40:33.755566Z     info    Reloaded WAL cache      {"log_id": "0_JGYV3W000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/1", "duration": "6.422ms"}
2022-03-18T12:40:33.816668Z     info    Meta data index for shard loaded        {"log_id": "0_JGYV3W000", "engine": "tsm1", "id": 1, "duration": "46.184ms"}
2022-03-18T12:40:33.834990Z     info    Opened shard    {"log_id": "0_JGYV3W000", "service": "store", "trace_id": "0_JGYVnW000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/1", "duration": "174.626ms"}
2022-03-18T12:40:33.889611Z     info    tsm1 WAL starting       {"log_id": "0_JGYV3W000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T12:40:33.905634Z     info    tsm1 WAL writing        {"log_id": "0_JGYV3W000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2"}
2022-03-18T12:40:33.965509Z     info    Opened file     {"log_id": "0_JGYV3W000", "engine": "tsm1", "service": "filestore", "path": "/var/lib/influxdb/data/artxdb/autogen/2/000000001-000000001.tsm", "id": 0, "duration": "8.700ms"}
2022-03-18T12:40:33.994594Z     info    Reloaded WAL cache      {"log_id": "0_JGYV3W000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/2", "duration": "6.514ms"}
2022-03-18T12:40:34.068803Z     info    Meta data index for shard loaded        {"log_id": "0_JGYV3W000", "engine": "tsm1", "id": 2, "duration": "53.142ms"}
2022-03-18T12:40:34.076085Z     info    Opened shard    {"log_id": "0_JGYV3W000", "service": "store", "trace_id": "0_JGYVnW000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "228.933ms"}
2022-03-18T12:40:34.086510Z     info    Open store (end)        {"log_id": "0_JGYV3W000", "service": "store", "trace_id": "0_JGYVnW000", "op_name": "tsdb_open", "op_event": "end", "op_elapsed": "603.696ms"}
run: open server: open tsdb store: function not implemented

The procedure was quiet simply.
I inserted just one data point, waited until I get the output that WAL file was auto removed. And shut down influxd cleanly with SIGTERM.

On next start of influxd I get the error output (see log above)

Here are the logs of the first run of the influxd 1.8.10 (that was ok)

 8888888           .d888 888                   8888888b.  888888b.
   888            d88P"  888                   888  "Y88b 888  "88b
   888            888    888                   888    888 888  .88P
   888   88888b.  888888 888 888  888 888  888 888    888 8888888K.
   888   888 "88b 888    888 888  888  Y8bd8P' 888    888 888  "Y88b
   888   888  888 888    888 888  888   X88K   888    888 888    888
   888   888  888 888    888 Y88b 888 .d8""8b. 888  .d88P 888   d88P
 8888888 888  888 888    888  "Y88888 888  888 8888888P"  8888888P"

2022-03-18T12:28:55.566370Z     info    InfluxDB starting       {"log_id": "0_JFsuUW000", "version": "1.8.10", "branch": "1.8", "commit": "688e697c51fd"}
2022-03-18T12:28:55.578179Z     info    Go runtime      {"log_id": "0_JFsuUW000", "version": "go1.13.8", "maxprocs": 1}
2022-03-18T12:28:55.700542Z     info    Using data dir  {"log_id": "0_JFsuUW000", "service": "store", "path": "/var/lib/influxdb/data"}
2022-03-18T12:28:55.727884Z     info    Compaction settings     {"log_id": "0_JFsuUW000", "service": "store", "max_concurrent_compactions": 1, "throughput_bytes_per_second": 50331648, "throughput_bytes_per_second_burst": 50331648}
2022-03-18T12:28:55.736637Z     info    Open store (start)      {"log_id": "0_JFsuUW000", "service": "store", "trace_id": "0_JFsvE0000", "op_name": "tsdb_open", "op_event": "start"}
2022-03-18T12:28:55.786675Z     info    tsm1 WAL starting       {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T12:28:55.799899Z     info    tsm1 WAL writing        {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2"}
2022-03-18T12:28:55.839917Z     info    Reloaded WAL cache      {"log_id": "0_JFsuUW000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/2", "duration": "5.267ms"}
2022-03-18T12:28:55.909826Z     info    Meta data index for shard loaded        {"log_id": "0_JFsuUW000", "engine": "tsm1", "id": 2, "duration": "55.158ms"}
2022-03-18T12:28:55.923688Z     info    Opened shard    {"log_id": "0_JFsuUW000", "service": "store", "trace_id": "0_JFsvE0000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "147.296ms"}
2022-03-18T12:28:55.972855Z     info    tsm1 WAL starting       {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "segment_size": 10485760}
2022-03-18T12:28:55.987941Z     info    tsm1 WAL writing        {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/1"}
2022-03-18T12:28:56.033192Z     info    Reloaded WAL cache      {"log_id": "0_JFsuUW000", "engine": "tsm1", "path": "/var/lib/influxdb/wal/artxdb/autogen/1", "duration": "6.171ms"}
2022-03-18T12:28:56.091590Z     info    Meta data index for shard loaded        {"log_id": "0_JFsuUW000", "engine": "tsm1", "id": 1, "duration": "43.064ms"}
2022-03-18T12:28:56.107952Z     info    Opened shard    {"log_id": "0_JFsuUW000", "service": "store", "trace_id": "0_JFsvE0000", "op_name": "tsdb_open", "index_version": "inmem", "path": "/var/lib/influxdb/data/artxdb/autogen/1", "duration": "170.389ms"}
2022-03-18T12:28:56.119976Z     info    Open store (end)        {"log_id": "0_JFsuUW000", "service": "store", "trace_id": "0_JFsvE0000", "op_name": "tsdb_open", "op_event": "end", "op_elapsed": "383.282ms"}
2022-03-18T12:28:56.178159Z     info    Opened service  {"log_id": "0_JFsuUW000", "service": "subscriber"}
2022-03-18T12:28:56.188145Z     info    Starting monitor service        {"log_id": "0_JFsuUW000", "service": "monitor"}
2022-03-18T12:28:56.191940Z     info    Registered diagnostics client   {"log_id": "0_JFsuUW000", "service": "monitor", "name": "build"}
2022-03-18T12:28:56.195503Z     info    Registered diagnostics client   {"log_id": "0_JFsuUW000", "service": "monitor", "name": "runtime"}
2022-03-18T12:28:56.199160Z     info    Registered diagnostics client   {"log_id": "0_JFsuUW000", "service": "monitor", "name": "network"}
2022-03-18T12:28:56.204187Z     info    Registered diagnostics client   {"log_id": "0_JFsuUW000", "service": "monitor", "name": "system"}
2022-03-18T12:28:56.207032Z     info    Starting precreation service    {"log_id": "0_JFsuUW000", "service": "shard-precreation", "check_interval": "10m", "advance_period": "30m"}
2022-03-18T12:28:56.211251Z     info    Starting snapshot service       {"log_id": "0_JFsuUW000", "service": "snapshot"}
2022-03-18T12:28:56.215968Z     info    Starting continuous query service       {"log_id": "0_JFsuUW000", "service": "continuous_querier"}
2022-03-18T12:28:56.224701Z     info    Starting HTTP service   {"log_id": "0_JFsuUW000", "service": "httpd", "authentication": true}
2022-03-18T12:28:56.234101Z     info    Auth is enabled but shared-secret is blank. BearerAuthentication is disabled.      {"log_id": "0_JFsuUW000", "service": "httpd"}
2022-03-18T12:28:56.288242Z     info    Listening on HTTP       {"log_id": "0_JFsuUW000", "service": "httpd", "addr": "0.0.0.0:8086", "https": false}
2022-03-18T12:28:56.300124Z     info    Starting retention policy enforcement service   {"log_id": "0_JFsuUW000", "service": "retention", "check_interval": "30m"}
2022-03-18T12:28:56.305618Z     info    Listening for signals   {"log_id": "0_JFsuUW000"}


2022-03-18T12:39:16.006854Z     info    Compacting cache        {"log_id": "0_JFsuUW000", "engine": "tsm1", "path": "/var/lib/influxdb/data/artxdb/autogen/2"}
2022-03-18T12:39:16.009553Z     info    Cache snapshot (start)  {"log_id": "0_JFsuUW000", "engine": "tsm1", "trace_id": "0_JGTmAG000", "op_name": "tsm1_cache_snapshot", "op_event": "start"}
2022-03-18T12:39:16.026060Z     info    Snapshot for path deduplicated  {"log_id": "0_JFsuUW000", "engine": "tsm1", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "2.224ms"}
2022-03-18T12:39:16.215548Z     info    Removing WAL file       {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2/_00001.wal"}
2022-03-18T12:39:16.236298Z     info    Snapshot for path written       {"log_id": "0_JFsuUW000", "engine": "tsm1", "trace_id": "0_JGTmAG000", "op_name": "tsm1_cache_snapshot", "path": "/var/lib/influxdb/data/artxdb/autogen/2", "duration": "226.695ms"}
2022-03-18T12:39:16.246657Z     info    Cache snapshot (end)    {"log_id": "0_JFsuUW000", "engine": "tsm1", "trace_id": "0_JGTmAG000", "op_name": "tsm1_cache_snapshot", "op_event": "end", "op_elapsed": "237.007ms"}


2022-03-18T12:39:26.074260Z   info    Signal received, initializing clean shutdown... {"log_id": "0_JFsuUW000"}
2022-03-18T12:39:26.079579Z     info    Waiting for clean shutdown...   {"log_id": "0_JFsuUW000"}
2022-03-18T12:39:26.092715Z     info    Shutting down monitor service   {"log_id": "0_JFsuUW000", "service": "monitor"}
[tcp] 2022/03/18 12:39:26 tcp.Mux: Listener at 127.0.0.1:8088 failed failed to accept a connection, closing all listeners - accept tcp 127.0.0.1:8088: use of closed network connection
2022-03-18T12:39:26.109787Z     info    Terminating precreation service {"log_id": "0_JFsuUW000", "service": "shard-precreation"}
2022-03-18T12:39:26.117413Z     info    Listener closed {"log_id": "0_JFsuUW000", "service": "snapshot"}
2022-03-18T12:39:26.131631Z     info    Terminating continuous query service    {"log_id": "0_JFsuUW000", "service": "continuous_querier"}
2022-03-18T12:39:26.155988Z     info    Closing retention policy enforcement service    {"log_id": "0_JFsuUW000", "service": "retention"}
2022-03-18T12:39:26.190651Z     info    Closing WAL file        {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/2"}
2022-03-18T12:39:26.175495Z     info    Closing WAL file        {"log_id": "0_JFsuUW000", "engine": "tsm1", "service": "wal", "path": "/var/lib/influxdb/wal/artxdb/autogen/1"}
2022-03-18T12:39:26.216679Z     info    Closed service  {"log_id": "0_JFsuUW000", "service": "subscriber"}
2022-03-18T12:39:26.227387Z     info    Server shutdown completed       {"log_id": "0_JFsuUW000"}

Jay_Clifford · March 21, 2022, 6:33pm

Hey @arturo,
Sorry for the late reply as I am currently travelling at the moment. Interesting issue, what type of ARM device are you running InfluxDB on? I am passing this to our edge team and see if they can investigate the route cause further.

arturo · March 22, 2022, 11:07am

Hi @Jay_Clifford,

it’s a proprietary hardware board with Renesas RZN1D controller and Debian 10 distro installed on it.

Jay_Clifford · March 23, 2022, 7:43pm

Hi @arturo,
So I have spoken with our edge team and here was their reply:
"
“function not implemented” is returned when a system call underneath Go is not found in the operating system. We see this when the operating system is a version older than we support, for instance.There’s usually no fix but upgrading the operating system. The error on shutdown is probably from madvise (my guess from looking where it might be generated: madvise)The error on startup could be from a number of system calls; it’s trying to create the data directory, so doing stat , and various directory creation and file opening system calls. Let me know if I can help more.
"

arturo · March 24, 2022, 3:19pm

Hi @Jay_Clifford,

thank you for your Answer!
This was the hint I was looking for!

It was the missing madvise syscall in linux kernel.
I compiled new kernel and now it seems that everything is working correctly.

Topic		Replies	Views
My influxdb can't start influxdb	8	18630	August 19, 2020
Influx will not start InfluxDB 2 influxdb , raspberry	1	4507	January 5, 2022
InfluxDB not starting on armbian error code 2	3	1101	July 5, 2022
Influxd error# run: open server: open tsdb store: function not implemented InfluxDB 1	0	606	March 2, 2022
Can't start InfluxDB! InfluxDB 1	1	601	September 21, 2021

InfluxDB does not start

Related topics