[systemd-devel] Per-connection socket activation not always running service

[John Pitney]

To check my understanding of how per-connection socket activation
works, I've tried to make a very simple socket-activated service which
runs any input through md5sum, writes md5sum's output to the journal,
and then sleeps for one second.  What I have works, but only
sometimes.  Frequently, no md5sum output appears in the journal, and
eventually the service goes into a failed state, but I don't see why.

Here are my unit files:

# cat /etc/systemd/system/md5.socket
[Unit]
Description=md5sum socket

[Socket]
ListenStream=8075
Accept=yes

[Install]
WantedBy=sockets.target
# cat /etc/systemd/system/md5 at .service
[Unit]
Description=md5sum service

[Service]
ExecStart=/usr/bin/sh -c '/usr/bin/md5sum ; sleep 1'
StandardInput=socket
StandardOutput=journal

Here, I see what to look for in the journal, possibly in some other order.

# for i in $(seq 1 8) ; do echo $i|md5sum ; done
b026324c6904b2a9cb4b88d6d61c81d1  -
26ab0db90d72e28ad0ba1e22ee510510  -
6d7fce9fee471194aa8b5b6e47267f03  -
48a24b70a0b376535542b996af517398  -
1dcca23355272056f04fe8bf20edfce0  -
9ae0ea9e3c9c6e1b9b6252c8395efdc1  -
84bc3da1b3e33a18e8d5e1bdd7a18d7a  -
c30f7472766d25af1dc80b3ffc9a58c7  -

Here, I send the same eight strings to the service.

# for i in $(seq 1 8) ; do echo $i|nc -c localhost 8075 & done

Only one of these (number 5) shows up with output in the journal.

# journalctl -b -u "md5*" --since "20:20:00"
-- Logs begin at Sat 2014-11-29 13:38:04 CST, end at Wed 2015-08-26
20:33:19 CDT. --
Aug 26 20:24:55 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55635).
Aug 26 20:24:55 archie-01 sh[24705]: 1dcca23355272056f04fe8bf20edfce0  -

If I try the same for loop a few more times, I got one round of all
eight md5sums appearing in the journal, but in the next round, I get a
few md5sums before I start getting errors.

# journalctl -b -u "md5*" --since "20:30:00" --no-pager
-- Logs begin at Sat 2014-11-29 13:38:04 CST, end at Wed 2015-08-26
20:36:16 CDT. --
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55643).
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55644).
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55645).
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55646).
Aug 26 20:35:12 archie-01 sh[24752]: 26ab0db90d72e28ad0ba1e22ee510510  -
Aug 26 20:35:12 archie-01 sh[24750]: b026324c6904b2a9cb4b88d6d61c81d1  -
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55647).
Aug 26 20:35:12 archie-01 sh[24756]: 6d7fce9fee471194aa8b5b6e47267f03  -
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55648).
Aug 26 20:35:12 archie-01 sh[24760]: 1dcca23355272056f04fe8bf20edfce0  -
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55649).
Aug 26 20:35:12 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55650).
Aug 26 20:35:12 archie-01 sh[24754]: c30f7472766d25af1dc80b3ffc9a58c7  -
Aug 26 20:35:12 archie-01 sh[24763]: 48a24b70a0b376535542b996af517398  -
Aug 26 20:35:12 archie-01 sh[24766]: 9ae0ea9e3c9c6e1b9b6252c8395efdc1  -
Aug 26 20:35:12 archie-01 sh[24768]: 84bc3da1b3e33a18e8d5e1bdd7a18d7a  -
Aug 26 20:36:16 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55651).
Aug 26 20:36:16 archie-01 sh[24813]: 6d7fce9fee471194aa8b5b6e47267f03  -
Aug 26 20:36:16 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55652).
Aug 26 20:36:16 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55653).
Aug 26 20:36:16 archie-01 sh[24816]: 1dcca23355272056f04fe8bf20edfce0  -
Aug 26 20:36:16 archie-01 sh[24818]: 48a24b70a0b376535542b996af517398  -
Aug 26 20:36:16 archie-01 systemd[1]: Started md5sum service (127.0.0.1:55657).
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 14-127.0.0.1:8075-127.0.0.1:55656.service: Failed to run 'start'
task: Transport endpoint is not connected
Aug 26 20:36:16 archie-01 systemd[1]: Failed to start md5sum service
(127.0.0.1:55656).
Aug 26 20:36:16 archie-01 sh[24821]: 84bc3da1b3e33a18e8d5e1bdd7a18d7a  -
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 14-127.0.0.1:8075-127.0.0.1:55656.service: Unit entered failed
state.
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 14-127.0.0.1:8075-127.0.0.1:55656.service: Failed with result
'resources'.
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 13-127.0.0.1:8075-127.0.0.1:55655.service: Failed to run 'start'
task: Transport endpoint is not connected
Aug 26 20:36:16 archie-01 systemd[1]: Failed to start md5sum service
(127.0.0.1:55655).
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 13-127.0.0.1:8075-127.0.0.1:55655.service: Unit entered failed
state.
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 13-127.0.0.1:8075-127.0.0.1:55655.service: Failed with result
'resources'.
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 12-127.0.0.1:8075-127.0.0.1:55654.service: Failed to run 'start'
task: Transport endpoint is not connected
Aug 26 20:36:16 archie-01 systemd[1]: Failed to start md5sum service
(127.0.0.1:55654).
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 12-127.0.0.1:8075-127.0.0.1:55654.service: Unit entered failed
state.
Aug 26 20:36:16 archie-01 systemd[1]:
md5 at 12-127.0.0.1:8075-127.0.0.1:55654.service: Failed with result
'resources'.

What do these error messages mean?

These unit files are probably not correct somehow---what should I
change to make this work, even when many connections are made
concurrently?

Thanks,
John