salt: Log filled with "Exception occurred while Subscriber handling stream: Already reading"

Description of Issue/Question

Hi, on a server running salt-minion and salt-master, the minion’s logfile was today filled (quite quickly) with the following message:

2018-08-12 06:25:10,762 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,762 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,762 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,763 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading
2018-08-12 06:25:10,764 [salt.transport.ipc][ERROR   ][25008] Exception occurred while Subscriber handling stream: Already reading

Stopping the minion service didn’t stop the process writing to the logfile, neither did SIGTERM - I only got rid of it with SIGKILL (PID 25008 here):

$ ps aux | grep [p]ython
root     24851  0.0  0.1 101600  6048 ?        S    Aug10   0:00 /usr/bin/python /usr/bin/salt-minion
root     24854  0.0  0.2 548420 11264 ?        Sl   Aug10   0:09 /usr/bin/python /usr/bin/salt-minion
root     25005  0.0  0.1 101600  6412 ?        S    Aug10   0:00 /usr/bin/python /usr/bin/salt-minion
root     25008 99.9  0.6 549964 27508 ?        Sl   Aug10 8403:05 /usr/bin/python /usr/bin/salt-minion

Setup

I don’t know what’s relevant here…

Steps to Reproduce Issue

Don’t know either 😕

Versions Report

Salt Version:
           Salt: 2017.7.2

Dependency Versions:
           cffi: Not Installed
       cherrypy: Not Installed
       dateutil: 1.5
      docker-py: Not Installed
          gitdb: 0.5.4
      gitpython: 0.3.2 RC1
          ioflo: Not Installed
         Jinja2: 2.7.2
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: 0.9.1
   msgpack-pure: Not Installed
 msgpack-python: 0.4.6
   mysql-python: 1.2.3
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 2.7.6 (default, Nov 23 2017, 15:49:48)
   python-gnupg: Not Installed
         PyYAML: 3.10
          PyZMQ: 14.4.0
           RAET: Not Installed
          smmap: 0.8.2
        timelib: Not Installed
        Tornado: 4.2.1
            ZMQ: 4.0.5

System Versions:
           dist: Ubuntu 14.04 trusty
         locale: ANSI_X3.4-1968
        machine: x86_64
        release: 3.19.0-80-generic
         system: Linux
        version: Ubuntu 14.04 trusty

Same version of minion, master, and common.

About this issue

Original URL
State: closed
Created 6 years ago
Reactions: 1
Comments: 47 (26 by maintainers)

Most upvoted comments

@elipsion in June I think.

DmitryKuzmenko on May 23, 2019

Awesome, much appreciated!

anitakrueger on May 14, 2019

Currently the fix is in all branches (2018.3, 2019.2 and develop). It will be released in the nearest builds.

DmitryKuzmenko on May 7, 2019

Had some time today to work on this. I confirmed my thinking I wrote here above. Tomorrow I’ll provide the description and solution.

DmitryKuzmenko on Nov 27, 2018

Getting the same here in our setup, about 10 or so of our minions are getting this and filling up drive space rapidly.

rochen-joshua on Nov 14, 2018

@furgerf it’s OK. What about the problem, I think we could try to catch this by code review. There are not many places where that subscriber is used. Did you do something on that minion right before? I see the strange exception report in your log 4 seconds before the issue happened. Did you restarted minion manually or by cron? Did minion execute some state or schedule task?

@Ch3LL I propose to mark it as a bug and put to the backlog. If we’d have more reports here, we could increase the severity of this.

DmitryKuzmenko on Aug 20, 2018