blocknotify fails to execute command, logs "runCommand error", continues to fail on every block until restart #11874

Running: bitcoin v0.15.0.1 Raspberry Pi 3 (Raspbian Stretch 9)

I have this blocknotify command in my bitcoin.conf: blocknotify=python /home/pi/bin/ClockBlocker/block.py %s ...which points to this script

I've been using this method and python script for years. Every now and then, and more often lately, the blocknotify stops working. blocknotify fails to run the command, and logs a runCommand error. The python script is not run at all, and never will for any future block. After stopping the node and restarting, behavior returns to normal.

I modified the python script to print the block height and hash when it runs for debugging, and ran bitcoind without -daemon to print the output of the python script to the console. In this instance, block 498761 is the last block where blocknotify runs as expected. Every new block after 498761 returns this "-1" error with no output from python, until bitcoind is restarted.

output of bitcoind (no -daemon):

--
(498759, '00000000000000000018e5f8d99dcd94aff8346319939b2800c840156b91a1bc')
--
(498760, '0000000000000000004d5c6ecd33753a2e0cbae60b40d74e26a949a87329f298')
--
(498761, '0000000000000000008263857816e81d68cb9e5e435bf82f1ff0d27af6e0743d')

--> output stops here

relevant chunk of .bitcoin/debug.log:

2017-12-11 16:05:00 UpdateTip: new best=00000000000000000018e5f8d99dcd94aff8346319939b2800c840156b91a1bc height=498759 version=0x20000000 log2_work=87.633707 tx=280733472 date='2017-12-11 16:04:31' progress=1.000000 cache=115.0MiB(1038368txo)
2017-12-11 16:09:17 receive version message: /Satoshi:0.15.1/: version 70015, blocks=498759, us=24.130.115.125:48770, peer=52
2017-12-11 16:12:44 Pre-allocating up to position 0xc00000 in rev01098.dat
2017-12-11 16:12:45 UpdateTip: new best=0000000000000000004d5c6ecd33753a2e0cbae60b40d74e26a949a87329f298 height=498760 version=0x20000000 log2_work=87.633748 tx=280736185 date='2017-12-11 16:12:59' progress=1.000000 cache=115.9MiB(1047092txo)
2017-12-11 16:23:01 receive version message: /Satoshi:0.15.1/: version 70015, blocks=498760, us=24.130.115.125:34049, peer=53
2017-12-11 16:24:13 connect() to 131.113.41.123:8333 failed after select(): Connection refused (111)
2017-12-11 16:26:00 UpdateTip: new best=0000000000000000008263857816e81d68cb9e5e435bf82f1ff0d27af6e0743d height=498761 version=0x20000000 log2_work=87.633789 tx=280738499 date='2017-12-11 16:25:29' progress=1.000000 cache=116.9MiB(1055950txo)
2017-12-11 16:27:56 receive version message: /Satoshi:0.14.2/: version 70015, blocks=498761, us=24.130.115.125:46283, peer=54
2017-12-11 16:29:02 connect() to 89.238.176.102:8333 failed after select(): Connection refused (111)
2017-12-11 16:29:14 UpdateTip: new best=0000000000000000007f7212b500b765878334c924af2bd83fe881ae91671dc2 height=498762 version=0x20000000 log2_work=87.63383 tx=280741423 date='2017-12-11 16:28:44' progress=1.000000 cache=121.5MiB(1060495txo)
2017-12-11 16:29:14 runCommand error: system(python /home/pi/ClockBlocker/block.py 0000000000000000007f7212b500b765878334c924af2bd83fe881ae91671dc2) returned -1
2017-12-11 16:29:23 UpdateTip: new best=00000000000000000045319a9d5a5031160b12b2dcccaf4ea537849440e0a07a height=498763 version=0x20000000 log2_work=87.633871 tx=280744233 date='2017-12-11 16:29:32' progress=1.000000 cache=121.9MiB(1064343txo)
2017-12-11 16:29:23 runCommand error: system(python /home/pi/ClockBlocker/block.py 00000000000000000045319a9d5a5031160b12b2dcccaf4ea537849440e0a07a) returned -1
2017-12-11 16:30:31 UpdateTip: new best=000000000000000000aa68479e13acf3035b0db7581fed7ce7c6304d6432a5f7 height=498764 version=0x20000000 log2_work=87.633912 tx=280746878 date='2017-12-11 16:30:07' progress=1.000000 cache=122.4MiB(1068597txo)
2017-12-11 16:30:31 runCommand error: system(python /home/pi/ClockBlocker/block.py 000000000000000000aa68479e13acf3035b0db7581fed7ce7c6304d6432a5f7) returned -1
2017-12-11 16:38:07 UpdateTip: new best=000000000000000000943e6a69087aa820688b2e188126d88b03972abbc226db height=498765 version=0x20000000 log2_work=87.633953 tx=280749414 date='2017-12-11 16:38:01' progress=1.000000 cache=123.0MiB(1074102txo)
2017-12-11 16:38:07 runCommand error: system(python /home/pi/ClockBlocker/block.py 000000000000000000943e6a69087aa820688b2e188126d88b03972abbc226db) returned -1
2017-12-11 16:38:39 socket send error Invalid argument (22)
2017-12-11 16:38:39 connect() to 104.243.34.58:8333 failed after select(): Connection refused (111)
2017-12-11 16:38:46 receive version message: /Satoshi:0.15.0.1/: version 70015, blocks=498765, us=24.130.115.125:44635, peer=55
2017-12-11 16:42:20 UpdateTip: new best=000000000000000000af50bce86fd0f49dc706a41fcd17d483c906f95490de08 height=498766 version=0x20000000 log2_work=87.633994 tx=280751495 date='2017-12-11 16:41:47' progress=1.000000 cache=123.5MiB(1078913txo)
2017-12-11 16:42:20 runCommand error: system(python /home/pi/ClockBlocker/block.py 000000000000000000af50bce86fd0f49dc706a41fcd17d483c906f95490de08) returned -1
2017-12-11 16:44:06 Pre-allocating up to position 0xd00000 in rev01098.dat
2017-12-11 16:44:06 UpdateTip: new best=00000000000000000018103b5fe48ffd6108f2928322cb555b54e8f2c731a8fc height=498767 version=0x20000000 log2_work=87.634035 tx=280753261 date='2017-12-11 16:44:39' progress=1.000000 cache=123.7MiB(1081313txo)
2017-12-11 16:44:06 runCommand error: system(python /home/pi/ClockBlocker/block.py 00000000000000000018103b5fe48ffd6108f2928322cb555b54e8f2c731a8fc) returned -1

How long does the script takes to execute?

I guess the error comes from the fact that a new thread is launched to run runCommand() which calls system(). Therefore you are probably running a lot of scripts at the same time. Maybe outputing errno there would help.

See https://stackoverflow.com/questions/17899164/calling-system-inside-a-c-loop-fails for a related discussion.

are you still hitting this @pinheadmz?

Not in a few months! Can't remember if I did anything to fix it. Could have been something like just increasing swap file size... Are you getting a similar error?

no was just following up, perhaps this can be closed now?