Bug 46708 - UMC System diagnostic writes paramico DEBUG messages to connector-s4.log (I swear!)
UMC System diagnostic writes paramico DEBUG messages to connector-s4.log (I s...
Product: UCS
Classification: Unclassified
Component: UMC - System diagnostic
UCS 4.3
Other Linux
: P5 normal (vote)
: UCS 4.3-0-errata
Assigned To: Arvid Requate
Felix Botner
Depends on:
  Show dependency treegraph
Reported: 2018-03-21 09:54 CET by Arvid Requate
Modified: 2018-03-28 13:28 CEST (History)
1 user (show)

See Also:
What kind of report is it?: ---
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2018-03-21 09:54:30 CET
Yesterday Felix observed log messages from paramico in connector-s4.log when running UMC diagnostic. Sounds crazy, but it's reproducible and apparently a collaboration of four software parts in UCS:

1. diagnostic/plugins/43_connectors4_rejects.py  instanciates the s4-Connector
2. The univention.s4connector.ucs class initializes univention.debug2,
   instructing python-logging to use connector-s4.log
3. diagnostic/plugins/01_ssh_connection.py uses python-paramico
4. a change of logging in python-paramico in UCS 4.3-0

Here's what get's logged. We still don't understand why paramico now logs DEBUG level messages:
01.03.2018 03:27:01,555 paramiko.transport (DEBUG  ): starting thread (client mode): 0x4f21fe50L
01.03.2018 03:27:01,563 paramiko.transport (DEBUG  ): Local version/idstring: SSH-2.0-paramiko_2.0.0
01.03.2018 03:27:01,563 paramiko.transport (DEBUG  ): Remote version/idstring: SSH-2.0-OpenSSH_7.4p1 Debian-10+deb9u2
01.03.2018 03:27:01,563 paramiko.transport (INFO   ): Connected (version 2.0, client OpenSSH_7.4p1)
01.03.2018 03:27:01,566 paramiko.transport (DEBUG  ): kex algos:[u'gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==', u'gss-group1-sha1-toWM5Slw5Ew8Mqkay+al2g==', u'gss-group14-sha1-toWM
5Slw5Ew8Mqkay+al2g==', u'curve25519-sha256', u'curve25519-sha256@libssh.org', u'ecdh-sha2-nistp256', u'ecdh-sha2-nistp384', u'ecdh-sha2-nistp521', u'diffie-hellman-group-excha
nge-sha256', u'diffie-hellman-group16-sha512', u'diffie-hellman-group18-sha512', u'diffie-hellman-group14-sha256', u'diffie-hellman-group14-sha1'] server key:[u'ssh-rsa', u'rs
a-sha2-512', u'rsa-sha2-256', u'ecdsa-sha2-nistp256'] client encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com',
 u'aes256-gcm@openssh.com'] server encrypt:[u'chacha20-poly1305@openssh.com', u'aes128-ctr', u'aes192-ctr', u'aes256-ctr', u'aes128-gcm@openssh.com', u'aes256-gcm@openssh.com'
] client mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-256-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac
-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hmac-sha1'] server mac:[u'umac-64-etm@openssh.com', u'umac-128-etm@openssh.com', u'hmac-sha2-2
56-etm@openssh.com', u'hmac-sha2-512-etm@openssh.com', u'hmac-sha1-etm@openssh.com', u'umac-64@openssh.com', u'umac-128@openssh.com', u'hmac-sha2-256', u'hmac-sha2-512', u'hma
c-sha1'] client compress:[u'none', u'zlib@openssh.com'] server compress:[u'none', u'zlib@openssh.com'] client lang:[u''] server lang:[u''] kex follows?False
01.03.2018 03:27:01,567 paramiko.transport (DEBUG  ): Kex agreed: diffie-hellman-group14-sha1
01.03.2018 03:27:01,567 paramiko.transport (DEBUG  ): Cipher agreed: aes128-ctr
01.03.2018 03:27:01,567 paramiko.transport (DEBUG  ): MAC agreed: hmac-sha2-256
01.03.2018 03:27:01,567 paramiko.transport (DEBUG  ): Compression agreed: none
01.03.2018 03:27:01,691 paramiko.transport (DEBUG  ): kex engine KexGroup14 specified hash_algo <built-in function openssl_sha1>
01.03.2018 03:27:01,693 paramiko.transport (DEBUG  ): Switch to new keys ...
01.03.2018 03:27:01,734 paramiko.transport (DEBUG  ): userauth is OK
01.03.2018 03:27:01,741 paramiko.transport (DEBUG  ): Authentication type (password) not permitted.
01.03.2018 03:27:01,741 paramiko.transport (DEBUG  ): Allowed methods: [u'publickey', u'gssapi-keyex', u'gssapi-with-mic', u'keyboard-interactive']
01.03.2018 03:27:01,746 paramiko.transport (DEBUG  ): userauth is OK
01.03.2018 03:27:01,793 paramiko.transport (INFO   ): Authentication (keyboard-interactive) successful!
01.03.2018 03:27:01,896 paramiko.transport (DEBUG  ): EOF in transport thread

The real fix would be to improve initialization of logging in the S4-Connector.
The workaround in the diagnostic module would be to raise the minimal llogging level for paramico:

logger = paramiko.util.logging.getLogger()

paramico kind of sucks (see Bug 45343 Comment 4).
Comment 1 Arvid Requate univentionstaff 2018-03-21 10:01:50 CET
0142766d9c | Add workaround
fcaabea8a1 | Advisory
Comment 2 Felix Botner univentionstaff 2018-03-21 10:53:05 CET
FAIL - yaml
OK - logging
Comment 3 Felix Botner univentionstaff 2018-03-21 10:58:19 CET
(In reply to Felix Botner from comment #2)
> FAIL - yaml
> OK - logging

no, it is not OK, the package has not been built, don't know why, but i can't see logs with 4.0.0-21 ?
Comment 4 Arvid Requate univentionstaff 2018-03-21 12:51:14 CET
Yes, sorry, package has been rebuilt now.
Resetting the univention-debug2 basicConfig logfile is too much of a hassle right now. We should rather fix that in univention.s4connector at some point.

3daf8ff89b | Advisory
Comment 5 Felix Botner univentionstaff 2018-03-21 13:37:49 CET
OK - no paramiko logs in connector log
OK - yaml
Comment 6 Arvid Requate univentionstaff 2018-03-28 13:28:38 CEST