Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

System tests fail on agent enrollment #4552

Closed
juliamagan opened this issue Sep 25, 2023 · 4 comments · Fixed by #4562
Closed

System tests fail on agent enrollment #4552

juliamagan opened this issue Sep 25, 2023 · 4 comments · Fixed by #4562
Assignees
Labels
level/task Task issue qa_known Issues that are already known by the QA team type/bug

Comments

@juliamagan
Copy link
Member

Description

During the tests launched in Release 4.5.3 - RC 1 - System tests, it has been seen that two tests consistently fail during the agent's enrollment, while waiting for the message:

Requesting a key from server:

These tests are not exactly the same, but similar, and fail at the same point, so the error could be related. We should investigate what could be happening.

@Deblintrake09
Copy link
Contributor

Deblintrake09 commented Sep 26, 2023

Research update

  • Replicated issue. Logs appear in manager but not on Agent.
Logs evidence
  • Agent logs
2023/09/26 23:53:59 wazuh-agentd[14906] debug_op.c:116 at _log_function(): DEBUG: Logging module auto-initialized
2023/09/26 23:53:59 wazuh-agentd[14906] main.c:139 at main(): DEBUG: Wazuh home directory: /var/ossec
2023/09/26 23:53:59 wazuh-agentd[14906] main.c:141 at main(): DEBUG: Started (pid: 14906).
2023/09/26 23:53:59 wazuh-agentd[14906] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/26 23:53:59 wazuh-agentd[14906] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/26 23:53:59 wazuh-agentd[14906] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/26 23:53:59 wazuh-agentd[14906] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/26 23:53:59 wazuh-agentd[14906] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/26 23:53:59 wazuh-agentd[14906] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/26 23:53:59 wazuh-execd: INFO: Started (pid: 14921).
2023/09/26 23:54:00 wazuh-agentd[14929] debug_op.c:116 at _log_function(): DEBUG: Logging module auto-initialized
2023/09/26 23:54:00 wazuh-agentd[14929] main.c:139 at main(): DEBUG: Wazuh home directory: /var/ossec
2023/09/26 23:54:00 wazuh-agentd[14929] main.c:141 at main(): DEBUG: Started (pid: 14929).
2023/09/26 23:54:00 wazuh-agentd[14929] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/26 23:54:00 wazuh-agentd[14929] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/26 23:54:00 wazuh-agentd[14929] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/26 23:54:00 wazuh-agentd[14929] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/26 23:54:00 wazuh-agentd[14929] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/26 23:54:00 wazuh-agentd[14929] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: Started (pid: 14944).
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/boot', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/etc', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mtab'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/hosts.deny'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mail/statistics'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random-seed'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random.seed'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/adjtime'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/httpd/logs'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/utmpx'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/wtmpx'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/cups/certs'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/dumpdates'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/svc/volatile'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/security'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/debug'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/dev/core'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6207): Ignore 'file' sregex '^/proc'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6207): Ignore 'file' sregex '.log$|.swp$'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6004): No diff for file: '/etc/ssl/private.key'
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6000): Starting daemon...
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6010): File integrity monitoring scan frequency: 43200 seconds
2023/09/26 23:54:01 wazuh-syscheckd: INFO: (6008): File integrity monitoring scan started.
2023/09/26 23:54:02 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/ossec/logs/active-responses.log'.
2023/09/26 23:54:02 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/log/dpkg.log'.
2023/09/26 23:54:02 wazuh-logcollector: INFO: Monitoring output of command(360): df -P
2023/09/26 23:54:02 wazuh-logcollector: INFO: Monitoring full output of command(360): netstat -tulpn | sed "s/\([[:alnum:]]\+\)\ \+[[:digit:]]\+\ \+[[:digit:]]\+\ \+\(.*\):\([[:digit:]]*\)\ \+\([0-9\.\:\*]\+\).\+\ \([[:digit:]]*\/[[:alnum:]\-]*\).*/\1 \2 == \3 == \4 \5/" | sort -k 4 -g | sed "s/ == \(.*\) ==/:\1/" | sed 1,2d
2023/09/26 23:54:02 wazuh-logcollector: INFO: Monitoring full output of command(360): last -n 20
2023/09/26 23:54:02 wazuh-logcollector: INFO: Started (pid: 14956).
2023/09/26 23:54:03 wazuh-modulesd: INFO: Started (pid: 14973).
2023/09/26 23:54:03 wazuh-modulesd:oscap: INFO: Module disabled. Exiting...
2023/09/26 23:54:03 wazuh-modulesd:agent-upgrade: INFO: (8153): Module Agent Upgrade started.
2023/09/26 23:54:03 wazuh-modulesd:ciscat: INFO: Module disabled. Exiting...
2023/09/26 23:54:03 sca: INFO: Module started.
2023/09/26 23:54:03 wazuh-modulesd:control: INFO: Starting control thread.
2023/09/26 23:54:03 wazuh-modulesd:osquery: INFO: Module disabled. Exiting...
2023/09/26 23:54:03 sca: INFO: Loaded policy '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/26 23:54:03 sca: INFO: Starting Security Configuration Assessment scan.
2023/09/26 23:54:03 wazuh-modulesd:syscollector: INFO: Module started.
2023/09/26 23:54:03 wazuh-modulesd:syscollector: INFO: Starting evaluation.
2023/09/26 23:54:03 sca: INFO: Starting evaluation of policy: '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/26 23:54:03 wazuh-modulesd:syscollector: INFO: Evaluation finished.
2023/09/26 23:54:21 rootcheck: INFO: Starting rootcheck scan.
2023/09/26 23:54:21 wazuh-syscheckd: INFO: Agent is now online. Process unlocked, continuing...
2023/09/26 23:54:22 wazuh-syscheckd: INFO: (6009): File integrity monitoring scan ended.
2023/09/26 23:54:23 sca: INFO: Evaluation finished for policy '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/26 23:54:23 sca: INFO: Security Configuration Assessment scan finished. Duration: 20 seconds.
2023/09/26 23:54:23 wazuh-modulesd: INFO: Agent is now online. Process unlocked, continuing...
  • Manager Logs
 tail -f /var/ossec/logs/ossec.log 
2023/09/26 23:53:41 wazuh-modulesd:syscollector: INFO: Stop received for Syscollector.
2023/09/26 23:53:41 wazuh-modulesd:syscollector: INFO: Module finished.
2023/09/26 23:53:41 wazuh-monitord: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:41 wazuh-logcollector: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:41 wazuh-remoted: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:41 wazuh-syscheckd: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:42 wazuh-analysisd: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:42 wazuh-execd: INFO: (1314): Shutdown received. Deleting responses.
2023/09/26 23:53:42 wazuh-execd: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:42 wazuh-db: INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:43 wazuh-authd[54251] main-server.c:969 at handler(): INFO: (1225): SIGNAL [(15)-(Terminated)] Received. Exit Cleaning...
2023/09/26 23:53:43 wazuh-authd[54251] main-server.c:793 at run_remote_server(): DEBUG: Remote server thread finished
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:706 at run_dispatcher(): DEBUG: Dispatch thread finished
2023/09/26 23:53:44 wazuh-authd[54251] local-server.c:164 at run_local_server(): DEBUG: Local server thread finished
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:827 at run_writer(): DEBUG: Dumping changes into disk.
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:849 at run_writer(): DEBUG: [Writer] OS_WriteKeys(): 221 µs.
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:859 at run_writer(): DEBUG: [Writer] OS_WriteTimestamps(): 100 µs.
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:945 at run_writer(): DEBUG: [Writer] Inserted agents: 0
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:946 at run_writer(): DEBUG: [Writer] Removed agents: 0
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:947 at run_writer(): DEBUG: [Writer] Loop: 0 ms.
2023/09/26 23:53:44 wazuh-authd[54251] main-server.c:527 at main(): INFO: Exiting...
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7616): List 'etc/lists/amazon/aws-eventnames' could not be loaded. Rule '80202' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80203'.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80203' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7617): Signature ID '80203' was not found and will be ignored in the 'if_sid' option of rule '80250'.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80250' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80251'.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80251' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7620): Signature ID '80251' was not found. Invalid 'if_matched_sid'.Rule '80252' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80253'.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80253' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7617): Signature ID '80253' was not found and will be ignored in the 'if_sid' option of rule '80254'.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80254' will be ignored.
2023/09/26 23:53:45 wazuh-analysisd: WARNING: (7620): Signature ID '80254' was not found. Invalid 'if_matched_sid'.Rule '80255' will be ignored.
2023/09/26 23:53:45 wazuh-modulesd: WARNING: A deprecated Vulnerability Detector configuration block was found. It will be ignored.
2023/09/26 23:53:45 wazuh-modulesd: ERROR: Unknown module 'key-request'
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7616): List 'etc/lists/amazon/aws-eventnames' could not be loaded. Rule '80202' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80203'.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7619): Empty 'if_sid' value. Rule '80203' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7617): Signature ID '80203' was not found and will be ignored in the 'if_sid' option of rule '80250'.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7619): Empty 'if_sid' value. Rule '80250' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80251'.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7619): Empty 'if_sid' value. Rule '80251' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7620): Signature ID '80251' was not found. Invalid 'if_matched_sid'.Rule '80252' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80253'.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7619): Empty 'if_sid' value. Rule '80253' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7617): Signature ID '80253' was not found and will be ignored in the 'if_sid' option of rule '80254'.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7619): Empty 'if_sid' value. Rule '80254' will be ignored.
2023/09/26 23:53:45 wazuh-testrule: WARNING: (7620): Signature ID '80254' was not found. Invalid 'if_matched_sid'.Rule '80255' will be ignored.
2023/09/26 23:53:46 wazuh-csyslogd: INFO: Remote syslog server not configured. Clean exit.
2023/09/26 23:53:46 wazuh-dbd: INFO: Database not configured. Clean exit.
2023/09/26 23:53:46 wazuh-integratord: INFO: Remote integrations not configured. Clean exit.
2023/09/26 23:53:46 wazuh-agentlessd: INFO: Not configured. Exiting.
2023/09/26 23:53:46 wazuh-authd[55847] debug_op.c:116 at _log_function(): DEBUG: Logging module auto-initialized
2023/09/26 23:53:46 wazuh-authd[55847] config.c:23 at authd_read_config(): DEBUG: Reading configuration 'etc/ossec.conf'
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:343 at main(): DEBUG: Wazuh home directory: /var/ossec
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:392 at main(): INFO: Started (pid: 55850).
2023/09/26 23:53:46 wazuh-authd[55847] ssl.c:75 at os_ssl_keys(): DEBUG: Returning CTX for server.
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:447 at main(): INFO: Accepting connections on port 1515. No password required.
2023/09/26 23:53:46 wazuh-authd[55847] keys.c:336 at OS_ReadKeys(): DEBUG: (1751): File client.keys not found or empty.
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:545 at run_dispatcher(): DEBUG: Dispatch thread ready.
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:723 at run_remote_server(): INFO: Setting network timeout to 1.000000 sec.
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:728 at run_remote_server(): DEBUG: Remote server ready.
2023/09/26 23:53:46 wazuh-authd[55847] local-server.c:89 at run_local_server(): DEBUG: Local server thread ready.
2023/09/26 23:53:46 wazuh-authd[55847] main-server.c:812 at run_writer(): DEBUG: Writer thread ready.
2023/09/26 23:53:47 wazuh-db: INFO: Started (pid: 55865).
2023/09/26 23:53:48 wazuh-execd: INFO: Started (pid: 55895).
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7616): List 'etc/lists/amazon/aws-eventnames' could not be loaded. Rule '80202' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80203'.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80203' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7617): Signature ID '80203' was not found and will be ignored in the 'if_sid' option of rule '80250'.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80250' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80251'.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80251' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7620): Signature ID '80251' was not found. Invalid 'if_matched_sid'.Rule '80252' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7617): Signature ID '80202' was not found and will be ignored in the 'if_sid' option of rule '80253'.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80253' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7617): Signature ID '80253' was not found and will be ignored in the 'if_sid' option of rule '80254'.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7619): Empty 'if_sid' value. Rule '80254' will be ignored.
2023/09/26 23:53:49 wazuh-analysisd: WARNING: (7620): Signature ID '80254' was not found. Invalid 'if_matched_sid'.Rule '80255' will be ignored.
2023/09/26 23:53:50 wazuh-analysisd: INFO: Total rules enabled: '6680'
2023/09/26 23:53:50 wazuh-analysisd: INFO: Started (pid: 55909).
2023/09/26 23:53:50 wazuh-analysisd: INFO: EPS limit disabled
2023/09/26 23:53:50 wazuh-analysisd: INFO: (7200): Logtest started
2023/09/26 23:53:50 wazuh-syscheckd: WARNING: The check_unixaudit option is deprecated in favor of the SCA module.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: Started (pid: 55970).
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/boot', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/etc', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mtab'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/hosts.deny'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mail/statistics'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random-seed'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random.seed'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/adjtime'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/httpd/logs'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/utmpx'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/wtmpx'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/cups/certs'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/dumpdates'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/svc/volatile'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/security'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/debug'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6207): Ignore 'file' sregex '.log$|.swp$'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6004): No diff for file: '/etc/ssl/private.key'
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6000): Starting daemon...
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6010): File integrity monitoring scan frequency: 43200 seconds
2023/09/26 23:53:50 wazuh-syscheckd: INFO: (6008): File integrity monitoring scan started.
2023/09/26 23:53:50 rootcheck: INFO: Starting rootcheck scan.
2023/09/26 23:53:50 rootcheck: ERROR: No unixaudit file: '/var/ossec/etc/shared/system_audit_rcl.txt'
2023/09/26 23:53:50 rootcheck: ERROR: No unixaudit file: '/var/ossec/etc/shared/system_audit_ssh.txt'
2023/09/26 23:53:50 rootcheck: ERROR: No unixaudit file: '/var/ossec/etc/shared/cis_debian_linux_rcl.txt'
2023/09/26 23:53:51 wazuh-syscheckd: INFO: (6009): File integrity monitoring scan ended.
2023/09/26 23:53:51 wazuh-remoted: INFO: Started (pid: 56009). Listening on port 1514/TCP (secure).
2023/09/26 23:53:51 wazuh-remoted: INFO: (1410): Reading authentication keys file.
2023/09/26 23:53:52 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/ossec/logs/active-responses.log'.
2023/09/26 23:53:52 wazuh-logcollector: ERROR: (1103): Could not open file '/var/log/messages' due to [(2)-(No such file or directory)].
2023/09/26 23:53:52 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/log/messages'.
2023/09/26 23:53:52 wazuh-logcollector: ERROR: (1103): Could not open file '/var/log/auth.log' due to [(2)-(No such file or directory)].
2023/09/26 23:53:52 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/log/auth.log'.
2023/09/26 23:53:52 wazuh-logcollector: ERROR: (1103): Could not open file '/var/log/syslog' due to [(2)-(No such file or directory)].
2023/09/26 23:53:52 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/log/syslog'.
2023/09/26 23:53:52 wazuh-logcollector: INFO: Monitoring output of command(360): df -P
2023/09/26 23:53:52 wazuh-logcollector: INFO: Monitoring full output of command(360): netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort
2023/09/26 23:53:52 wazuh-logcollector: INFO: Monitoring full output of command(360): last -n 5
2023/09/26 23:53:52 wazuh-logcollector: INFO: Started (pid: 56053).
2023/09/26 23:53:52 wazuh-monitord: INFO: Started (pid: 56069).
2023/09/26 23:53:54 wazuh-modulesd: WARNING: A deprecated Vulnerability Detector configuration block was found. It will be ignored.
2023/09/26 23:53:54 wazuh-modulesd: ERROR: Unknown module 'key-request'
2023/09/26 23:53:54 wazuh-modulesd: INFO: Started (pid: 56081).
2023/09/26 23:53:54 wazuh-modulesd:agent-upgrade: INFO: (8153): Module Agent Upgrade started.
2023/09/26 23:53:54 wazuh-modulesd:control: INFO: Starting control thread.
2023/09/26 23:53:54 wazuh-modulesd:download: INFO: Module started.
2023/09/26 23:53:54 wazuh-modulesd:database: INFO: Module started.
2023/09/26 23:53:54 wazuh-modulesd:task-manager: INFO: (8200): Module Task Manager started.
2023/09/26 23:53:54 wazuh-modulesd:oscap: INFO: Module disabled. Exiting...
2023/09/26 23:53:54 wazuh-modulesd:syscollector: INFO: Module started.
2023/09/26 23:53:54 wazuh-modulesd:syscollector: INFO: Starting evaluation.
2023/09/26 23:53:54 wazuh-modulesd:syscollector: INFO: Evaluation finished.
2023/09/26 23:53:57 rootcheck: INFO: Ending rootcheck scan.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:577 at run_dispatcher(): INFO: New connection from 172.24.27.3
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:620 at run_dispatcher(): DEBUG: Request received: <OSSEC A:'wazuh-agent1'
>
2023/09/26 23:54:00 wazuh-authd[55847] auth.c:104 at w_auth_parse_data(): INFO: Received request for a new agent (wazuh-agent1) from: 172.24.27.3
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:650 at run_dispatcher(): INFO: Agent key generated for 'wazuh-agent1' (requested by any)
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:827 at run_writer(): DEBUG: Dumping changes into disk.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:849 at run_writer(): DEBUG: [Writer] OS_WriteKeys(): 205 µs.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:859 at run_writer(): DEBUG: [Writer] OS_WriteTimestamps(): 106 µs.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:867 at run_writer(): DEBUG: [Writer] Performing insert([001] wazuh-agent1).
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:874 at run_writer(): DEBUG: [Writer] wdb_insert_agent(): 422 µs.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:889 at run_writer(): DEBUG: [Writer] wdb_set_agent_groups_csv(): 0 µs.
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:945 at run_writer(): DEBUG: [Writer] Inserted agents: 1
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:946 at run_writer(): DEBUG: [Writer] Removed agents: 0
2023/09/26 23:54:00 wazuh-authd[55847] main-server.c:947 at run_writer(): DEBUG: [Writer] Loop: 0 ms.
2023/09/26 23:54:01 wazuh-remoted: INFO: (1409): Authentication file changed. Updating.
2023/09/26 23:54:01 wazuh-remoted: INFO: (1410): Reading authentication keys file.

@damarisg damarisg added the qa_known Issues that are already known by the QA team label Sep 27, 2023
@Deblintrake09
Copy link
Contributor

Research update

During research it was found that the Agent does not print the connection events, even though the connection completes properly.

  • Agent logs
# cat /var/ossec/logs/ossec.log 
2023/09/27 17:35:00 wazuh-agentd[5833] debug_op.c:116 at _log_function(): DEBUG: Logging module auto-initialized
2023/09/27 17:35:00 wazuh-agentd[5833] main.c:139 at main(): DEBUG: Wazuh home directory: /var/ossec
2023/09/27 17:35:00 wazuh-agentd[5833] main.c:141 at main(): DEBUG: Started (pid: 5833).
2023/09/27 17:35:00 wazuh-agentd[5833] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/27 17:35:00 wazuh-agentd[5833] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/27 17:35:00 wazuh-agentd[5833] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/27 17:35:00 wazuh-agentd[5833] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/27 17:35:00 wazuh-agentd[5833] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/27 17:35:00 wazuh-agentd[5833] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/27 17:35:00 wazuh-execd: INFO: Started (pid: 5847).
2023/09/27 17:35:01 wazuh-agentd[5856] debug_op.c:116 at _log_function(): DEBUG: Logging module auto-initialized
2023/09/27 17:35:01 wazuh-agentd[5856] main.c:139 at main(): DEBUG: Wazuh home directory: /var/ossec
2023/09/27 17:35:01 wazuh-agentd[5856] main.c:141 at main(): DEBUG: Started (pid: 5856).
2023/09/27 17:35:01 wazuh-agentd[5856] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/27 17:35:01 wazuh-agentd[5856] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/27 17:35:01 wazuh-agentd[5856] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/27 17:35:01 wazuh-agentd[5856] agent_op.c:219 at os_read_agent_profile(): DEBUG: Calling os_read_agent_profile().
2023/09/27 17:35:01 wazuh-agentd[5856] agent_op.c:238 at os_read_agent_profile(): DEBUG: os_read_agent_profile() = [debian, debian10]
2023/09/27 17:35:01 wazuh-agentd[5856] config.c:424 at ReadConfig(): DEBUG: agent_config element does not have any attributes.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: Started (pid: 5871).
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/boot', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/etc', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/bin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6003): Monitoring path: '/usr/sbin', with options 'size | permissions | owner | group | mtime | inode | hash_md5 | hash_sha1 | hash_sha256 | scheduled'.
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mtab'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/hosts.deny'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/mail/statistics'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random-seed'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/random.seed'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/adjtime'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/httpd/logs'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/utmpx'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/wtmpx'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/cups/certs'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/dumpdates'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/etc/svc/volatile'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/security'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/sys/kernel/debug'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6206): Ignore 'file' entry '/dev/core'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6207): Ignore 'file' sregex '^/proc'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6207): Ignore 'file' sregex '.log$|.swp$'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6004): No diff for file: '/etc/ssl/private.key'
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6000): Starting daemon...
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6010): File integrity monitoring scan frequency: 43200 seconds
2023/09/27 17:35:02 wazuh-syscheckd: INFO: (6008): File integrity monitoring scan started.
2023/09/27 17:35:03 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/ossec/logs/active-responses.log'.
2023/09/27 17:35:03 wazuh-logcollector: INFO: (1950): Analyzing file: '/var/log/dpkg.log'.
2023/09/27 17:35:03 wazuh-logcollector: INFO: Monitoring output of command(360): df -P
2023/09/27 17:35:03 wazuh-logcollector: INFO: Monitoring full output of command(360): netstat -tulpn | sed "s/\([[:alnum:]]\+\)\ \+[[:digit:]]\+\ \+[[:digit:]]\+\ \+\(.*\):\([[:digit:]]*\)\ \+\([0-9\.\:\*]\+\).\+\ \([[:digit:]]*\/[[:alnum:]\-]*\).*/\1 \2 == \3 == \4 \5/" | sort -k 4 -g | sed "s/ == \(.*\) ==/:\1/" | sed 1,2d
2023/09/27 17:35:03 wazuh-logcollector: INFO: Monitoring full output of command(360): last -n 20
2023/09/27 17:35:03 wazuh-logcollector: INFO: Started (pid: 5883).
2023/09/27 17:35:04 wazuh-modulesd: INFO: Started (pid: 5900).
2023/09/27 17:35:04 wazuh-modulesd:agent-upgrade: INFO: (8153): Module Agent Upgrade started.
2023/09/27 17:35:04 wazuh-modulesd:oscap: INFO: Module disabled. Exiting...
2023/09/27 17:35:04 wazuh-modulesd:ciscat: INFO: Module disabled. Exiting...
2023/09/27 17:35:04 wazuh-modulesd:osquery: INFO: Module disabled. Exiting...
2023/09/27 17:35:04 sca: INFO: Module started.
2023/09/27 17:35:04 wazuh-modulesd:control: INFO: Starting control thread.
2023/09/27 17:35:04 sca: INFO: Loaded policy '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/27 17:35:04 sca: INFO: Starting Security Configuration Assessment scan.
2023/09/27 17:35:04 wazuh-modulesd:syscollector: INFO: Module started.
2023/09/27 17:35:04 wazuh-modulesd:syscollector: INFO: Starting evaluation.
2023/09/27 17:35:04 sca: INFO: Starting evaluation of policy: '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/27 17:35:05 wazuh-modulesd:syscollector: INFO: Evaluation finished.
2023/09/27 17:35:22 wazuh-syscheckd: INFO: Agent is now online. Process unlocked, continuing...
2023/09/27 17:35:22 rootcheck: INFO: Starting rootcheck scan.
2023/09/27 17:35:23 wazuh-syscheckd: INFO: (6009): File integrity monitoring scan ended.
2023/09/27 17:35:25 wazuh-modulesd: INFO: Agent is now online. Process unlocked, continuing...
2023/09/27 17:35:25 sca: INFO: Evaluation finished for policy '/var/ossec/ruleset/sca/cis_debian10.yml'
2023/09/27 17:35:25 sca: INFO: Security Configuration Assessment scan finished. Duration: 21 seconds.
2023/09/27 17:35:33 rootcheck: INFO: Ending rootcheck scan.
  • Manager Logs
2023/09/27 17:34:55 wazuh-modulesd:database: INFO: Module started.
2023/09/27 17:34:55 wazuh-modulesd:control: INFO: Starting control thread.
2023/09/27 17:34:55 wazuh-modulesd:task-manager: INFO: (8200): Module Task Manager started.
2023/09/27 17:34:55 wazuh-modulesd:syscollector: INFO: Module started.
2023/09/27 17:34:55 wazuh-modulesd:syscollector: INFO: Starting evaluation.
2023/09/27 17:34:55 wazuh-modulesd:syscollector: INFO: Evaluation finished.
2023/09/27 17:34:58 rootcheck: INFO: Ending rootcheck scan.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:577 at run_dispatcher(): INFO: New connection from 172.24.27.3
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:620 at run_dispatcher(): DEBUG: Request received: <OSSEC A:'wazuh-agent1'
>
2023/09/27 17:35:01 wazuh-authd[47596] auth.c:104 at w_auth_parse_data(): INFO: Received request for a new agent (wazuh-agent1) from: 172.24.27.3
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:650 at run_dispatcher(): INFO: Agent key generated for 'wazuh-agent1' (requested by any)
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:827 at run_writer(): DEBUG: Dumping changes into disk.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:849 at run_writer(): DEBUG: [Writer] OS_WriteKeys(): 215 µs.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:859 at run_writer(): DEBUG: [Writer] OS_WriteTimestamps(): 84 µs.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:867 at run_writer(): DEBUG: [Writer] Performing insert([001] wazuh-agent1).
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:874 at run_writer(): DEBUG: [Writer] wdb_insert_agent(): 304 µs.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:889 at run_writer(): DEBUG: [Writer] wdb_set_agent_groups_csv(): 0 µs.
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:945 at run_writer(): DEBUG: [Writer] Inserted agents: 1
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:946 at run_writer(): DEBUG: [Writer] Removed agents: 0
2023/09/27 17:35:01 wazuh-authd[47596] main-server.c:947 at run_writer(): DEBUG: [Writer] Loop: 0 ms.
2023/09/27 17:35:02 wazuh-remoted: INFO: (1409): Authentication file changed. Updating.
2023/09/27 17:35:02 wazuh-remoted: INFO: (1410): Reading authentication keys file.
  • Check agent connection
root@wazuh-manager: ~# /var/ossec/bin/agent_control -i 001

Wazuh agent_control. Agent information:
   Agent ID:   001
   Agent Name: wazuh-agent1
   IP address: any
   Status:     Active

   Operating system:    Linux |wazuh-agent1 |5.15.0-69-generic |#76-Ubuntu SMP Fri Mar 17 17:35:01 UTC 2023 |x86_64
   Client version:      Wazuh v4.5.3
   Configuration hash:  ab73af41699f13fdd81903b5f23d8d00
   Shared file hash:    4a8724b20dee0124ff9656783c490c4e
   Last keep alive:     1695824815

   Syscheck last started at:  Wed Sep 27 17:35:16 2023
   Syscheck last ended at:    Wed Sep 27 16:36:14 2023
  • Check agent keys in agent and manager
root@wazuh-agent1: ~# cat /var/ossec/etc/client.keys 
001 wazuh-agent1 any 20415d66056b98b0959c875326066cd976fbb7f1a5712b433a59b4484c433fb1

root@wazuh-manager: ~# cat /var/ossec/etc/client.keys 
001 wazuh-agent1 any 20415d66056b98b0959c875326066cd976fbb7f1a5712b433a59b4484c433fb1

@wazuhci wazuhci moved this from In progress to Backlog in Release 4.5.3 Sep 27, 2023
@cborla cborla self-assigned this Sep 27, 2023
@wazuhci wazuhci moved this from Backlog to In progress in Release 4.5.3 Sep 27, 2023
@vikman90
Copy link
Member

After a meeting with @juliamagan, we've found that the test's function clear_file() is creating a new file etc/ossec.log with these permissions:

rw--r--r-- root root

This means that wazuh-agentd is unable to write into ossec.log after dropping its permissions.

We should consider either fixing the newly created ossec.log or simply deleting it as the daemons are expected to create it with the correct permissions.

Let me give this issue back to the QA team.

@juliamagan juliamagan assigned juliamagan and unassigned cborla Sep 28, 2023
@wazuhci wazuhci removed this from Release 4.5.3 Sep 28, 2023
@juliamagan juliamagan linked a pull request Sep 28, 2023 that will close this issue
@wazuhci wazuhci moved this to In progress in Release 4.5.3 Sep 28, 2023
@wazuhci wazuhci moved this from In progress to In review in Release 4.5.3 Sep 28, 2023
@verdx
Copy link
Contributor

verdx commented Sep 28, 2023

LGTM!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
level/task Task issue qa_known Issues that are already known by the QA team type/bug
Projects
No open projects
Status: Done
Development

Successfully merging a pull request may close this issue.

6 participants