ansiblepexpect

Ansible Expect module timeout, but command has been completed


I am developing Ansible playbook for manipulating GLPI server instance, and right now, I am dealing with database upgrade command. The command is interactive and requires user input, for which I am using Ansible Expect module.
The problem occurs when I run the DB upgrade task: ansible-playbook command will output an error saying that the command exceeded timeout. But the cherry on a pie is that the DB upgrade command actually completes and the DB is upgraded.
What I tried so far is raising Expect module timeout from default 30 secs to 60, 120 and 180, then trying also null timeout as a last resort.

Here is the command output as I ran it directly through SSH:

/var/www/glpi$ sudo php bin/console db:update
Some optional system requirements are missing. Run "php bin/console glpi:system:check_requirements" for more details.
    +-----------------------+-----------+-------------------------------------------------+,
    |                       | Current   | Targets                                         |
    +-----------------------+-----------+-------------------------------------------------+
    | Database host         | #OMITTED HOST IP# |                                                 |
    | Database name         | #OMITTED DB NAME#  |                                                 |
    | Database user         | #OMITTED USERNAME#  |                                                 |
    | GLPI version          | 9.5.8     | 10.0.2                                          |
    | GLPI database version | 9.5.7     | 10.0.2@a130db99c7d9b131c2e2ea59fe0d6260fe93d831 |
    +-----------------------+-----------+-------------------------------------------------+
    Checking database schema integrity...
    Database schema is OK.
    Do you want to continue? [Yes/no]<STDIN>
    ========================================= Update to 10.0.0 =========================================
    GLPI cache has been changed and will not use anymore APCu or Wincache extensions. Use "php bin/console cache:configure" command to configure cache system.
    ** New rights has been added for database, you should review ACLs after update
    ** New rights has been added for inventory, you should review ACLs after update
    ** New rights has been added for pendingreason, you should review ACLs after update
    ** New rights has been added for recurrentchange, you should review ACLs after update
    ** New rights has been added for itilfollowuptemplate, you should review ACLs after update
    "utf8mb4" support requires additional migration which can be performed via the "php bin/console glpi:migration:utf8mb4" command.
    ========================================= Update to 10.0.1 =========================================
    ** New rights has been added for rule_location, you should review ACLs after update
    ========================================= Update to 10.0.2 =========================================
    Migration done.
    We need your help to improve GLPI and the plugins ecosystem!
    Since GLPI 9.2, we’ve introduced a new statistics feature called “Telemetry”, that anonymously with your permission, sends data to our telemetry website.
    Once sent, usage statistics are aggregated and made available to a broad range of GLPI developers.
    Let us know your usage to improve future versions of GLPI and its plugins!
    Do you want to send "usage statistics"? [Yes/no]<STDIN>

The places for user input are marked with <STDIN>.
Below is the task I wrote:

- name: "Run database upgrade"
  tags:
    - glpi_upgrade_upgradedb
    - upgrade_glpi_database
  become: true
  expect:
    chdir: "{{ install_path }}"
    command: "php bin/console db:update"
    echo: true
    timeout: 60
    responses:
      .*Do you want to continue.*: "Yes"
      .*Do you want to send .usage statistics..*: "No"

And this is what I get when I run the task:

fatal: [#OMITTED HOST IP#]: FAILED! => {
"changed": true,
"cmd": "php bin/console db:update",
"delta": "0:00:18.428251",
"end": "2022-07-20 13:36:22.018696",
"invocation": {
    "module_args": {
        "chdir": "/var/www/glpi",
        "command": "php bin/console db:update",
        "creates": null,
        "echo": true,
        "removes": null,
        "responses": {
            ".*Do you want to continue.*": "Yes",
            ".*Do you want to send \"usage statistics\".*": "No"
        },
        "timeout": 60
    }
},
"msg": "command exceeded timeout",
"rc": null,
"start": "2022-07-20 13:36:03.590445",
"stdout": "\u001b[33mSome optional system requirements are missing. Run \"php bin/console glpi:system:check_requirements\" for more details.\u001b[39m\r\n+-----------------------+-----------+-------------------------------------------------+\r\n|\u001b[32m                       \u001b[39m|\u001b[32m Current   \u001b[39m|\u001b[32m Targets                                         \u001b[39m|\r\n+-----------------------+-----------+-------------------------------------------------+\r\n| Database host         | localhost |                                                 |\r\n| Database name         | app_GLPI  |                                                 |\r\n| Database user         | app_GLPI  |                                                 |\r\n| GLPI version          | 9.5.8     | 10.0.2                                          |\r\n| GLPI database version | 9.5.7     | 10.0.2@a130db99c7d9b131c2e2ea59fe0d6260fe93d831 |\r\n+-----------------------+-----------+-------------------------------------------------+\r\n\u001b[33mChecking database schema integrity...\u001b[39m\r\n\u001b[32mDatabase schema is OK.\u001b[39m\r\nDo you want to continue? [Yes/no]Yes\r\n\u001b[32m========================================= Update to 10.0.0 =========================================\u001b[39m\r\n\u001b[33mGLPI cache has been changed and will not use anymore APCu or Wincache extensions. Use \"php bin/console cache:configure\" command to configure cache system.\u001b[39m\r\n\u001b[33m** New rights has been added for database, you should review ACLs after update                      \u001b[39m\r\n\u001b[33m** New rights has been added for inventory, you should review ACLs after update                     \u001b[39m\r\n\u001b[33m** New rights has been added for pendingreason, you should review ACLs after update                 \u001b[39m\r\n\u001b[33m** New rights has been added for recurrentchange, you should review ACLs after update               \u001b[39m\r\n\u001b[33m** New rights has been added for itilfollowuptemplate, you should review ACLs after update          \u001b[39m\r\n\u001b[33m\"utf8mb4\" support requires additional migration which can be performed via the \"php bin/console glpi:migration:utf8mb4\" command.\u001b[39m\r\n\u001b[32m========================================= Update to 10.0.1 =========================================\u001b[39m\r\n\u001b[33m** New rights has been added for rule_location, you should review ACLs after update                 \u001b[39m\r\n\u001b[32m========================================= Update to 10.0.2 =========================================\u001b[39m\r\n\u001b[32mMigration done.\u001b[39m\r\n\u001b[33mWe need your help to improve GLPI and the plugins ecosystem!\u001b[39m\r\n\u001b[33mSince GLPI 9.2, we’ve introduced a new statistics feature called “Telemetry”, that anonymously with your permission, sends data to our telemetry website.\u001b[39m\r\n\u001b[33mOnce sent, usage statistics are aggregated and made available to a broad range of GLPI developers.\u001b[39m\r\n\u001b[33mLet us know your usage to improve future versions of GLPI and its plugins!\u001b[39m\r\nDo you want to send \"usage statistics\"? [Yes/no]No",
"stdout_lines": [
    "\u001b[33mSome optional system requirements are missing. Run \"php bin/console glpi:system:check_requirements\" for more details.\u001b[39m",
    "+-----------------------+-----------+-------------------------------------------------+",
    "|\u001b[32m                       \u001b[39m|\u001b[32m Current   \u001b[39m|\u001b[32m Targets                                         \u001b[39m|",
    "+-----------------------+-----------+-------------------------------------------------+",
    "| Database host         | #OMITTED HOST IP# |                                                 |",
    "| Database name         | #OMITTED DB NAME#  |                                                 |",
    "| Database user         | #OMITTED USERNAME#  |                                                 |",
    "| GLPI version          | 9.5.8     | 10.0.2                                          |",
    "| GLPI database version | 9.5.7     | 10.0.2@a130db99c7d9b131c2e2ea59fe0d6260fe93d831 |",
    "+-----------------------+-----------+-------------------------------------------------+",
    "\u001b[33mChecking database schema integrity...\u001b[39m",
    "\u001b[32mDatabase schema is OK.\u001b[39m",
    "Do you want to continue? [Yes/no]Yes",
    "\u001b[32m========================================= Update to 10.0.0 =========================================\u001b[39m",
    "\u001b[33mGLPI cache has been changed and will not use anymore APCu or Wincache extensions. Use \"php bin/console cache:configure\" command to configure cache system.\u001b[39m",
    "\u001b[33m** New rights has been added for database, you should review ACLs after update                      \u001b[39m",
    "\u001b[33m** New rights has been added for inventory, you should review ACLs after update                     \u001b[39m",
    "\u001b[33m** New rights has been added for pendingreason, you should review ACLs after update                 \u001b[39m",
    "\u001b[33m** New rights has been added for recurrentchange, you should review ACLs after update               \u001b[39m",
    "\u001b[33m** New rights has been added for itilfollowuptemplate, you should review ACLs after update          \u001b[39m",
    "\u001b[33m\"utf8mb4\" support requires additional migration which can be performed via the \"php bin/console glpi:migration:utf8mb4\" command.\u001b[39m",
    "\u001b[32m========================================= Update to 10.0.1 =========================================\u001b[39m",
    "\u001b[33m** New rights has been added for rule_location, you should review ACLs after update                 \u001b[39m",
    "\u001b[32m========================================= Update to 10.0.2 =========================================\u001b[39m",
    "\u001b[32mMigration done.\u001b[39m",
    "\u001b[33mWe need your help to improve GLPI and the plugins ecosystem!\u001b[39m",
    "\u001b[33mSince GLPI 9.2, we’ve introduced a new statistics feature called “Telemetry”, that anonymously with your permission, sends data to our telemetry website.\u001b[39m",
    "\u001b[33mOnce sent, usage statistics are aggregated and made available to a broad range of GLPI developers.\u001b[39m",
    "\u001b[33mLet us know your usage to improve future versions of GLPI and its plugins!\u001b[39m",
    "Do you want to send \"usage statistics\"? [Yes/no]No"
    ]
}

As you can see, question regexes will match, the questions are correctly answered, and the DB upgrade command is completed, only Ansible is throwing a timeout error. My opinion on this behavior is that there must be something what makes Ansible think it's a question with undefined response and it's waiting for input, so it fails with timeout.

Any ideas how could I fix this?
Thanks for help in advance;


Solution

  • Okay, so I debugged the entire DB upgrade command, and noticed that at each changelog message, for example "New rights have been added for database, you should review ACLs after update", there is at least 3 seconds pause. This can actually act like a question and throw a timeout error.

    That's how after googling and experimenting, I ended up installing TCL Expect on the GLPI server, replacing Ansible Expect module with Shell one, and running this inline script:

    spawn php {/var/www/glpi/bin/console} {db:update}
    expect {.*Do you want to continue.*}
    send "Yes\n"
    expect {.*New rights.*}
    send ""
    expect {.*php bin/console.*}
    send ""
    expect {.*Do you want to send .usage statistics..*}
    send "No\n"
    expect eof
    return 0
    

    This resulted into sending empty string on a changelog message output and actually eliminated the timeout.